shell> prompt very sluggish when typing first word on WSL

[topolarity]

Using this expect script to test:

#!/usr/bin/expect

spawn julia +1.10
expect "julia>"
send -- ";"
expect "shell>" {
    send -- "echo \"hello\"\r"
    expect -re "hello\r\n$"
}
expect "shell>" {
    send -- "echo \"hello\"\r"
    expect -re "hello\r\n$"
}
expect "shell>" {
    send -- "echo \"hello\"\r"
    expect -re "hello\r\n$"
}
expect "shell>" {
    send -- "echo \"hello\"\r"
    expect -re "hello\r\n$"
}
expect "shell>" {
    send -- "echo \"hello\"\r"
    expect -re "hello\r\n$"
}
expect "shell>" {
    send "\x03\x04\r"
}
expect eof

On 1.10:

$ time julia +1.10 -e ""
julia +1.10 -e ""  0.38s user 0.46s system 276% cpu 0.304 total ; start-up time only
$ time ./test_1.10.expect
expect ./test_1.10.expect  0.00s user 0.01s system 2% cpu 0.443 total ; start-up time + 5 shell commands

On latest nightly:

$ time ../../tmp/julia-c9bc2ffd52/bin/julia -e ""
../../tmp/julia-c9bc2ffd52/bin/julia -e ""  0.98s user 0.52s system 152% cpu 0.982 total ; start-up time only
$ time ./test_nightly.expect
./test_nightly.expect  0.00s user 0.01s system 0% cpu 6.719 total ; start-up time + 5 shell commands

Start-up time is 3x slower. Entering 5 shell commands takes 6.7 seconds instead of half a second on 1.10. The slow down seems to be specifically when typing the first word, for some reason.

Happens even when running with no shell customizations (zsh --no-rcs).

julia> versioninfo()
Julia Version 1.11.0-DEV.1203
Commit c9bc2ffd52e (2024-01-05 15:45 UTC)
Build Info:
  Official https://julialang.org/ release
Platform Info:
  OS: Linux (x86_64-linux-gnu)
  CPU: 12 × 12th Gen Intel(R) Core(TM) i7-1255U
  WORD_SIZE: 64
  LLVM: libLLVM-15.0.7 (ORCJIT, alderlake)
Threads: 1 default, 0 interactive, 1 GC (on 12 virtual cores)

[oscardssmith]

I assume the cause was moving repl out of the sysimage

[ViralBShah]

I assume this is due to #52769.

[topolarity]

This issue is specifically for the sluggish-ness when typing the first word of each shell> command, which does not seem to improve after warming up.

It takes over a second for expect to enter each shell command, so that e.g. inputing fifty in a row takes over a minute.

[PallHaraldsson]

It IS slower for me but only 601.0 ms today's julia-0cb5a0ecd4 master on vs 303.8 ms on 1.10 on Linux

However this keeps getting faster (50% faster min.):
$ hyperfine 'julia-0cb5a0ecd4/bin/julia -e ""'
Benchmark 1: julia-0cb5a0ecd4/bin/julia -e ""
Time (mean ± σ): 175.3 ms ± 13.4 ms [User: 192.5 ms, System: 124.3 ms]
Range (min … max): 145.1 ms … 197.1 ms 15 runs

[IanButterworth]

I don't see any lag on master so can someone who does see if this improves it
#52783

[IanButterworth]

Are those who see this lag using or have used -O3 at all?

[topolarity]

I don't see any lag on master so can someone who does see if this improves it
#52783

No improvement to the shell> delay, unfortunately. The slowdown is exactly the same for the first word of every command, so it's probably not a precompile problem in general?

Are those who see this lag using or have used -O3 at all?

Nope, not using -O3 here

[topolarity]

Ah, here's a clue.

Running with strace shows Julia crawling many directories in the root of my filesystem with each character I type:

readlink("/sbin", "usr/sbin", 1023)     = 8
readlink("/usr", 0x7fa6f55e96c0, 1023)  = -1 EINVAL (Invalid argument)
readlink("/usr/sbin", 0x7fa6f55e96c0, 1023) = -1 EINVAL (Invalid argument)
readlink("/bin", "usr/bin", 1023)       = 7
readlink("/usr", 0x7fa6f55e96c0, 1023)  = -1 EINVAL (Invalid argument)
readlink("/usr/bin", 0x7fa6f55e96c0, 1023) = -1 EINVAL (Invalid argument)
readlink("/usr", 0x7fa6f55e96c0, 1023)  = -1 EINVAL (Invalid argument)
readlink("/usr/games", 0x7fa6f55e96c0, 1023) = -1 EINVAL (Invalid argument)
openat(AT_FDCWD, "/usr/games", O_RDONLY|O_NONBLOCK|O_CLOEXEC|O_DIRECTORY) = 22
newfstatat(22, "", {st_mode=S_IFDIR|0755, st_size=4096, ...}, AT_EMPTY_PATH) = 0
getdents64(22, 0x1303280 /* 2 entries */, 32768) = 48
getdents64(22, 0x1303280 /* 0 entries */, 32768) = 0
close(22)                               = 0
readlink("/usr", 0x7fa6f55e96c0, 1023)  = -1 EINVAL (Invalid argument)
readlink("/usr/local", 0x7fa6f55e96c0, 1023) = -1 EINVAL (Invalid argument)
readlink("/usr/local/games", 0x7fa6f55e96c0, 1023) = -1 EINVAL (Invalid argument)
openat(AT_FDCWD, "/usr/local/games", O_RDONLY|O_NONBLOCK|O_CLOEXEC|O_DIRECTORY) = 22
newfstatat(22, "", {st_mode=S_IFDIR|0755, st_size=4096, ...}, AT_EMPTY_PATH) = 0
getdents64(22, 0x1303280 /* 2 entries */, 32768) = 48
getdents64(22, 0x1303280 /* 0 entries */, 32768) = 0
close(22)                               = 0
readlink("/usr", 0x7fa6f55e96c0, 1023)  = -1 EINVAL (Invalid argument)
readlink("/usr/lib", 0x7fa6f55e96c0, 1023) = -1 EINVAL (Invalid argument)
readlink("/usr/lib/wsl", 0x7fa6f55e96c0, 1023) = -1 EINVAL (Invalid argument)
readlink("/usr/lib/wsl/lib", 0x7fa6f55e96c0, 1023) = -1 EINVAL (Invalid argument)
openat(AT_FDCWD, "/usr/lib/wsl/lib", O_RDONLY|O_NONBLOCK|O_CLOEXEC|O_DIRECTORY) = 22
newfstatat(22, "", {st_mode=S_IFDIR|0755, st_size=40, ...}, AT_EMPTY_PATH) = 0
getdents64(22, 0x1303280 /* 5 entries */, 32768) = 152
getdents64(22, 0x1303280 /* 0 entries */, 32768) = 0
close(22)                               = 0
readlink("/mnt", 0x7fa6f55e96c0, 1023)  = -1 EINVAL (Invalid argument)
readlink("/mnt/c", 0x7fa6f55e96c0, 1023) = -1 EINVAL (Invalid argument)
readlink("/mnt/c/VulkanSDK", 0x7fa6f55e96c0, 1023) = -1 EINVAL (Invalid argument)
...

I see 176 statx(), 157 readlink(), 76 getdents64(), 35 openat() and a few others.

In total, there are over 500 syscalls for each key press.

I'm running in WSL2 so /mnt/c/ is the root of my Windows installation and is particularly slow to crawl.

In 1.10, Julia does no such crawling and executed only a few basic I/O syscalls on each keypress:

shell> ) = 39
epoll_wait(5, [], 1024, 0)              = 0
epoll_wait(5, [], 1024, 0)              = 0
epoll_wait(5, [{events=EPOLLIN, data={u32=12, u64=12}}], 1024, -1) = 1
read(12, "e", 65536)                    = 1
epoll_wait(5, [], 1024, 0)              = 0
ioctl(15, TIOCGWINSZ, {ws_row=36, ws_col=143, ws_xpixel=0, ws_ypixel=0}) = 0
write(15, "e", 1e)                       = 1
epoll_wait(5, [], 1024, 0)              = 0
epoll_wait(5, [], 1024, 0)              = 0
epoll_wait(5,

[KristofferC]

My guess is that could be the new REPL complete preview thing?

I don't see why it would crawl that much though...

[IanButterworth]

Maybe the hinting should cache readdir until the next prompt command entry?

[IanButterworth]

Some ideas

1. We buffer readdir for tab completion

• kick off readdir, if it takes longer than a certain time, return the progress so far
• continue readdir in the background
• any future readdir requests read from the buffer, however far along it is
• buffer is emptied at some point (after time has passed, or REPL mode switch, or something)

2. allow any keypress to gracefully stop the hint calculation. But I'm not sure how we'd do that..

3. we spawn hint completion calculation and only use the result if a key hasn't been pressed before return

[topolarity]

On top of the improvements to the usage of readdir, it would be nice to look into why it's scanning the root of the drive in the first place. I'd understand that if I typed cd /etc/... but that's not what's happening here

edit: At @IanButterworth's suggestion I checked my PATH and indeed that is what it's scanning with every keypress. I think it's the default behavior of WSL to automatically append the Windows %PATH% in the Linux VM.