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

Excise REPL and its dependencies from sysimg #51399

Merged
merged 4 commits into from
Sep 23, 2023
Merged

Excise REPL and its dependencies from sysimg #51399

merged 4 commits into from
Sep 23, 2023

Conversation

vchuravy
Copy link
Member

Needs #51189 for proper precompilation of Pkg.

Moves the precompilation of the REPL into it's own pkgimg.
Similar to #51350, but without moving any code out of Base.

@vchuravy vchuravy added REPL Julia's REPL (Read Eval Print Loop) excision Removal of code from Base or the repository labels Sep 19, 2023
@vchuravy
Copy link
Member Author

Positive startup impact for ./julia -e "exit()" ~30ms

But just ./julia feels less snappy. Haven't found a way to measure that quantitatively.

sysimage.mk Outdated Show resolved Hide resolved
@LilithHafner
Copy link
Member

But just ./julia feels less snappy. Haven't found a way to measure that quantitatively.

function time_repl_startup(julia_cmd="./julia")
    @async begin sleep(1); println("please press ^d") end
    buf = IOBuffer()
    t0 = time()
    run(pipeline(`$julia_cmd --startup-file=no -ie 'atreplinit(_->println(time()))'`, buf))
    s = String(take!(buf))
    parse(Float64, strip(match(r"\n\n\d\.\d\d\d\d+e\d\n", s).match))-t0
end

@rfourquet
Copy link
Member

But just ./julia feels less snappy. Haven't found a way to measure that quantitatively.

Another way suggested by Jameson iirc: just $ time julia followed by exit() will show the user time.

@LilithHafner
Copy link
Member

For me, "snappiness" refers to elapsed wall-clock time so reported user time might be misleading in the presence of CPU utilization other than 100% (either less or more).

@vchuravy
Copy link
Member Author

image

So looks like we spend time in codegen.

base/client.jl Outdated Show resolved Hide resolved
@vchuravy
Copy link
Member Author

So the extra-overhead is coming from extendedterminfo. Which uses broadcast (so costly to compile). That's 454ms xD

@vchuravy vchuravy mentioned this pull request Sep 20, 2023
@vchuravy vchuravy changed the base branch from master to kc/move_out_pkg September 20, 2023 22:58
Base automatically changed from kc/move_out_pkg to master September 21, 2023 02:42
@vchuravy vchuravy marked this pull request as ready for review September 21, 2023 03:22
@vchuravy
Copy link
Member Author

Would be great if folks try this out on different machines and see if they think the latency is now okay.

@jakobnissen
Copy link
Contributor

jakobnissen commented Sep 21, 2023

I tried this PR out. Julia's REPL itself does launch perceptably slower (perhaps 100-150 ms slower, but don't know how to measure it), but once the banner appears, the REPL is responsive immediately with no latency.
I agree this is fine. No-one is going to miss 100 ms when launching an interactive REPL.

@LilithHafner
Copy link
Member

LilithHafner commented Sep 21, 2023

So... it turns out my recommendation above underreports time till the "julia>" prompt appears because the atreplinit hooks run noticeably before the prompt appears. I wrote a Python script to benchmark time till julia> appears and runtime of hello world without a repl.

Results:

x@x dev % python latency_tests.py
system info:
Julia Version 1.9.3
Commit bed2cd540a1 (2023-08-24 14:43 UTC)
Build Info:
  Official https://julialang.org/ release
Platform Info:
  OS: macOS (arm64-apple-darwin22.4.0)
  CPU: 8 × Apple M2
  WORD_SIZE: 64
  LIBM: libopenlibm
  LLVM: libLLVM-14.0.6 (ORCJIT, apple-m1)
  Threads: 1 on 4 virtual cores
Environment:
  JULIA_EDITOR = code
master:
  o  | Version 1.11.0-DEV.525 (2023-09-21)
 o o | Commit 85c96b9c45* (0 days old master)
pr:
  o  | Version 1.11.0-DEV.526 (2023-09-21)
 o o | vc/excise_repl/f9ef95ee77* (fork: 2 commits, 0 days)
                min/med/mean (ms)
master repl:    424/437/438
pr repl:        351/365/376
master no repl: 151/158/173
pr no repl:     139/148/148
Script
from subprocess import Popen, PIPE, STDOUT
from time import time, sleep
import statistics

def repl_startup_time(exe):
    sleep(.3)
    t0 = time()
    p = Popen(exe + " --startup-file=no", stdout = PIPE, stderr = STDOUT, shell = True)
    str = []
    end = "julia>"
    while True:
        out = p.stdout.read(1)
        if out == b'':
            raise RuntimeError("Unexpected end")
        else:
            str.append(out.decode("utf-8"))
            if len(str) > len(end) and ''.join(str[-len(end):]) == end:
                break
    # print(''.join(str))
    t1 = time()
    p.kill()
    sleep(.3)
    return t1 - t0

def no_repl_startup_time(exe):
    sleep(.3)
    t0 = time()
    p = Popen(exe + " --startup-file=no -e 'println(sqrt(2))'", stdout = PIPE, stderr = STDOUT, shell = True)
    p.wait()
    # print(p.stdout.read())
    t1 = time()
    sleep(.3)
    return t1 - t0

def process(fun, exe, n):
    data = [fun(exe) for _ in range(n)]
    mn, med, mean = min(data), statistics.median(data), statistics.mean(data)
    return "{:.0f}/{:.0f}/{:.0f}".format(1000*mn, 1000*med, 1000*mean)

print("system info:")
p = Popen("julia --startup-file=no -e 'using InteractiveUtils; versioninfo()'", shell = True)
p.wait()
print("master:")
p = Popen("julia/julia --startup-file=no -e 'Base.banner(short=true)'", shell = True)
p.wait()
print("pr:")
p = Popen("julia2/julia --startup-file=no -e 'Base.banner(short=true)'", shell = True)
p.wait()

process(repl_startup_time, "julia/julia", 3)
process(repl_startup_time, "julia2/julia", 3)
process(no_repl_startup_time, "julia/julia", 3)
process(no_repl_startup_time, "julia2/julia", 3)

print("                min/med/mean (ms)")
print("master repl:    " + process(repl_startup_time, "julia/julia", 30))
print("pr repl:        " + process(repl_startup_time, "julia2/julia", 30))
print("master no repl: " + process(no_repl_startup_time, "julia/julia", 30))
print("pr no repl:     " + process(no_repl_startup_time, "julia2/julia", 30))

According to my measurements, this PR is great for startup times. It would be nice to include this sort of end to end startup time benchmarking in BaseBenchmarks.jl.

@vchuravy
Copy link
Member Author

master repl:    424/437/438
pr repl:        351/365/376

I don't quite trust this... It feels slower, but maybe its more that I have a debug build on?

@LilithHafner
Copy link
Member

I also don't trust it.

Testing this out interactively in VS code and MacOS Terminal revealed some issues

VS Code
Screenshot 2023-09-21 at 10 30 55 AM

MacOS Terminal
Screenshot 2023-09-21 at 10 33 18 AM

We should make sure CI catches these issues and also fix them.

@LilithHafner
Copy link
Member

One way to measure latency with REPL is to take a screen recording...

@vchuravy
Copy link
Member Author

What is your environment? This looks like you are missing @stdlib in your load path.

@vchuravy
Copy link
Member Author

@LilithHafner I made the debug message more useful.

@KristofferC
Copy link
Member

I usually record a gif and count the frames until I see the julia repl prompt.

@LilithHafner
Copy link
Member

LilithHafner commented Sep 21, 2023

What is @plots?

https://discourse.julialang.org/t/10-15-minute-ttfp-with-plots-jl-please-help/92636/53?u=lilith

And the temp directory in front?

https://discourse.julialang.org/t/tip-macro-to-install-use-package-in-temporary-environment/103190/2?u=lilith
(though I think I got this idea originally from @oxinabox a long time ago, I can't find the link to that)

Original source: JuliaLang/Pkg.jl#2669 (comment)

Also if you could do `JULIA_DEBUG=loading`.
x@x dev % export JULIA_DEBUG=loading
x@x dev % julia2/julia              
┌ Debug: Loading object cache file /Users/x/.julia/compiled/v1.11/OrderedCollections/LtT3J_Oju8X.dylib for OrderedCollections [bac558e1-5e72-5ebc-8fee-abe8a469f55d]
└ @ Base loading.jl:1058
┌ Debug: Loading object cache file /Users/x/.julia/dev/julia2/usr/share/julia/compiled/v1.11/UUIDs/SIw1t_g0NYI.dylib for UUIDs [cf7118a7-6976-5b1a-9a39-7adc72f591a4]
└ @ Base loading.jl:1058
┌ Debug: Loading object cache file /Users/x/.julia/dev/julia2/usr/share/julia/compiled/v1.11/Base64/D7K0n_g0NYI.dylib for Base64 [2a0f44e3-6c83-55bd-87e4-b1978d98bd5f]
└ @ Base loading.jl:1058
┌ Debug: Loading object cache file /Users/x/.julia/dev/julia2/usr/share/julia/compiled/v1.11/Markdown/AREjX_g0NYI.dylib for Markdown [d6f4376e-aef5-505a-96c1-9c027394607a]
└ @ Base loading.jl:1058
┌ Debug: Loading object cache file /Users/x/.julia/dev/julia2/usr/share/julia/compiled/v1.11/InteractiveUtils/0TrXF_g0NYI.dylib for InteractiveUtils [b77e0a4c-d291-57a0-90e8-8db25a27a240]
└ @ Base loading.jl:1058
┌ Debug: Loading object cache file /Users/x/.julia/compiled/v1.11/CodeTracking/a3E2l_Oju8X.dylib for CodeTracking [da1fd8a2-8d9e-5ec2-8556-3022fb5608a2]
└ @ Base loading.jl:1058
┌ Debug: Loading object cache file /Users/x/.julia/compiled/v1.11/JuliaInterpreter/PliIn_Oju8X.dylib for JuliaInterpreter [aa1ae85d-cabe-5617-a682-6adf51b2e16a]
└ @ Base loading.jl:1058
┌ Debug: Loading object cache file /Users/x/.julia/compiled/v1.11/LoweredCodeUtils/zWkaN_Oju8X.dylib for LoweredCodeUtils [6f1432cf-f94c-5a45-995e-cdbf5db27b0b]
└ @ Base loading.jl:1058
┌ Debug: Loading object cache file /Users/x/.julia/dev/julia2/usr/share/julia/compiled/v1.11/Unicode/E4Hzs_g0NYI.dylib for Unicode [4ec0a83e-493e-50e2-b9ac-8f72acf5a8f5]
└ @ Base loading.jl:1058
┌ Debug: Loading object cache file /Users/x/.julia/dev/julia2/usr/share/julia/compiled/v1.11/REPL/u0gqU_g0NYI.dylib for REPL [3fa0cd96-eef1-5676-8a61-b3b8758bbffb]
└ @ Base loading.jl:1058
┌ Debug: Loading object cache file /Users/x/.julia/dev/julia2/usr/share/julia/compiled/v1.11/Serialization/zGad9_g0NYI.dylib for Serialization [9e88b42a-f829-5b0c-bbe9-9e923198166b]
└ @ Base loading.jl:1058
┌ Debug: Loading object cache file /Users/x/.julia/dev/julia2/usr/share/julia/compiled/v1.11/Distributed/Pq94q_g0NYI.dylib for Distributed [8ba89e20-285c-5b6f-9357-94700520ee1b]
└ @ Base loading.jl:1058
┌ Debug: Loading object cache file /Users/x/.julia/dev/julia2/usr/share/julia/compiled/v1.11/Printf/3FQLY_g0NYI.dylib for Printf [de0858da-6303-5e67-8744-51eddeeeb8d7]
└ @ Base loading.jl:1058
┌ Debug: Loading object cache file /Users/x/.julia/dev/julia2/usr/share/julia/compiled/v1.11/Dates/p8See_g0NYI.dylib for Dates [ade2ca70-3891-5945-98fb-dc099432e06a]
└ @ Base loading.jl:1058
┌ Debug: Loading object cache file /Users/x/.julia/dev/julia2/usr/share/julia/compiled/v1.11/TOML/mjrwE_g0NYI.dylib for TOML [fa267f1f-6049-4f14-aa54-33bafae1ed76]
└ @ Base loading.jl:1058
┌ Debug: Loading object cache file /Users/x/.julia/dev/julia2/usr/share/julia/compiled/v1.11/NetworkOptions/J8H6s_g0NYI.dylib for NetworkOptions [ca575930-c2e3-43a9-ace4-1e988b2c1908]
└ @ Base loading.jl:1058
┌ Debug: Loading object cache file /Users/x/.julia/dev/julia2/usr/share/julia/compiled/v1.11/MbedTLS_jll/u5NEn_g0NYI.dylib for MbedTLS_jll [c8ffd9c3-330d-5841-b78e-0817d7145fa1]
└ @ Base loading.jl:1058
┌ Debug: Loading object cache file /Users/x/.julia/dev/julia2/usr/share/julia/compiled/v1.11/LibSSH2_jll/K6mup_g0NYI.dylib for LibSSH2_jll [29816b5a-b9ab-546f-933c-edad1886dfa8]
└ @ Base loading.jl:1058
┌ Debug: Loading object cache file /Users/x/.julia/dev/julia2/usr/share/julia/compiled/v1.11/LibGit2_jll/nfCpg_g0NYI.dylib for LibGit2_jll [e37daf67-58a4-590a-8e99-b0245dd2ffc5]
└ @ Base loading.jl:1058
┌ Debug: Loading object cache file /Users/x/.julia/dev/julia2/usr/share/julia/compiled/v1.11/LibGit2/xrYJZ_g0NYI.dylib for LibGit2 [76f85450-5226-5b5a-8eaa-529ad045b433]
└ @ Base loading.jl:1058
┌ Debug: Loading object cache file /Users/x/.julia/dev/julia2/usr/share/julia/compiled/v1.11/ArgTools/aGHFV_g0NYI.dylib for ArgTools [0dad84c5-d112-42e6-8d28-ef12dabb789f]
└ @ Base loading.jl:1058
┌ Debug: Loading object cache file /Users/x/.julia/dev/julia2/usr/share/julia/compiled/v1.11/nghttp2_jll/KTGSA_g0NYI.dylib for nghttp2_jll [8e850ede-7688-5339-a07c-302acd2aaf8d]
└ @ Base loading.jl:1058
┌ Debug: Loading object cache file /Users/x/.julia/dev/julia2/usr/share/julia/compiled/v1.11/LibCURL_jll/9JWaY_g0NYI.dylib for LibCURL_jll [deac9b47-8bc7-5906-a0fe-35ac56dc84c0]
└ @ Base loading.jl:1058
┌ Debug: Loading object cache file /Users/x/.julia/dev/julia2/usr/share/julia/compiled/v1.11/MozillaCACerts_jll/XKIUi_g0NYI.dylib for MozillaCACerts_jll [14a3606d-f60d-562e-9121-12d972cd8159]
└ @ Base loading.jl:1058
┌ Debug: Loading object cache file /Users/x/.julia/dev/julia2/usr/share/julia/compiled/v1.11/LibCURL/ht49g_g0NYI.dylib for LibCURL [b27032c2-a3e7-50c8-80cd-2d36dbcbfd21]
└ @ Base loading.jl:1058
┌ Debug: Loading object cache file /Users/x/.julia/dev/julia2/usr/share/julia/compiled/v1.11/Downloads/eiA4B_g0NYI.dylib for Downloads [f43a241f-c20a-4ad4-852c-f6b1247861c6]
└ @ Base loading.jl:1058
┌ Debug: Loading object cache file /Users/x/.julia/compiled/v1.11/Tar/G9ZYP_Oju8X.dylib for Tar [a4e569a6-e804-4fa4-b0f3-eef7a1d5b13e]
└ @ Base loading.jl:1058
┌ Debug: Loading object cache file /Users/x/.julia/dev/julia2/usr/share/julia/compiled/v1.11/p7zip_jll/dfuGM_g0NYI.dylib for p7zip_jll [3f19e933-33d8-53b3-aaab-bd5110c3b7a0]
└ @ Base loading.jl:1058
┌ Debug: Loading object cache file /Users/x/.julia/dev/julia2/usr/share/julia/compiled/v1.11/Logging/PWFjL_g0NYI.dylib for Logging [56ddb016-857b-54e1-b83d-db4d58db5568]
└ @ Base loading.jl:1058
┌ Debug: Loading object cache file /Users/x/.julia/compiled/v1.11/Pkg/tUTdb_Oju8X.dylib for Pkg [44cfe95a-1eb2-52ea-b672-e2afdf69b78f]
└ @ Base loading.jl:1058
┌ Debug: Loading object cache file /Users/x/.julia/compiled/v1.11/Revise/M1Qoh_Oju8X.dylib for Revise [295af30f-e4ad-537b-8983-00126c2a3abe]
└ @ Base loading.jl:1058
┌ Warning: REPL provider not available: using basic fallback
│   LOAD_PATH = "/var/folders/hc/fn82kz1j5vl8w7lwd4l079y80000gn/T/jl_lLtqGH:@:@v#.#:@stdlib:@Plots"
└ @ Base client.jl:452
               _
   _       _ _(_)_     |  Documentation: https://docs.julialang.org
  (_)     | (_) (_)    |
   _ _   _| |_  __ _   |  Type "?" for help, "]?" for Pkg help.
  | | | | | | |/ _` |  |
  | | |_| | | | (_| |  |  Version 1.11.0-DEV.529 (2023-09-21)
 _/ |\__'_|_|_|\__'_|  |  vc/excise_repl/c7c81f491a* (fork: 4 commits, 0 days)
|__/                   |

ENV["JULIA_DEBUG"]
julia> "loading"

Maybe run without your Startup-File?

This fixes it, but my startup file is currently fine on master, so I think this is a regression of some sort.

I'll try to distill my startup file to a MWE.

@vchuravy
Copy link
Member Author

It's particularly weird that we can load Pkg, but not REPL. Pkg depends on REPL.

@LilithHafner
Copy link
Member

The culprit in my startup.jl file seems to be using Revise

x@x dev % cat ../config/startup.jl
using Revise
x@x dev % julia2/julia 
┌ Warning: REPL provider not available: using basic fallback
│   LOAD_PATH = "@:@v#.#:@stdlib"
└ @ Base client.jl:452
               _
   _       _ _(_)_     |  Documentation: https://docs.julialang.org
  (_)     | (_) (_)    |
   _ _   _| |_  __ _   |  Type "?" for help, "]?" for Pkg help.
  | | | | | | |/ _` |  |
  | | |_| | | | (_| |  |  Version 1.11.0-DEV.529 (2023-09-21)
 _/ |\__'_|_|_|\__'_|  |  vc/excise_repl/c7c81f491a* (fork: 4 commits, 0 days)
|__/                   |

x@x dev % rm ../config/startup.jl 
x@x dev % julia2/julia           
               _
   _       _ _(_)_     |  Documentation: https://docs.julialang.org
  (_)     | (_) (_)    |
   _ _   _| |_  __ _   |  Type "?" for help, "]?" for Pkg help.
  | | | | | | |/ _` |  |
  | | |_| | | | (_| |  |  Version 1.11.0-DEV.529 (2023-09-21)
 _/ |\__'_|_|_|\__'_|  |  vc/excise_repl/c7c81f491a* (fork: 4 commits, 0 days)
|__/                   |

julia> 

@LilithHafner
Copy link
Member

A test case that covers this for me is running

./julia --startup-file=no -ie "using Revise" 

at the command line. Does that test case fail on your machine too? Regardless, I'm not sure how to do this within Julia's testing framework.

@vchuravy
Copy link
Member Author

Okay loading Revise breaks the REPL_MODULE_REF hook for some reason.

@vchuravy vchuravy changed the title Excise REPL from sysimg. Excise REPL and it's dependencies from sysimg. Sep 22, 2023
@giordano giordano changed the title Excise REPL and it's dependencies from sysimg. Excise REPL and its dependencies from sysimg Sep 22, 2023
@vchuravy vchuravy merged commit 2defa57 into master Sep 23, 2023
7 of 8 checks passed
@vchuravy vchuravy deleted the vc/excise_repl branch September 23, 2023 00:45
Comment on lines +143 to +144
# @which is undefined
@test_broken v == ("false\nREPL: InteractiveUtilstrue\n", true)
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This has introduced a distracting/confusing error show into CI

N5N3 added a commit to N5N3/julia that referenced this pull request Oct 1, 2023
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
excision Removal of code from Base or the repository REPL Julia's REPL (Read Eval Print Loop)
Projects
None yet
Development

Successfully merging this pull request may close these issues.

7 participants