Attaching a new session is much slower when not using `prompt_prefix = ""`

[injust]

What happened

When I removed prompt_prefix = "" from my shpool config, attaching a new session started taking ~3 seconds.

What I expected to happen

With prompt_prefix = "" in my shpool config, attaching a new session is almost instant. I expected this to stay the same.

To Reproduce

1. Use the following config:

prompt_prefix = ""

[[keybinding]]
action = "detach"
binding = "Ctrl-a d"

2. shpool attach test and then exit the session
3. Comment out prompt_prefix in the config
4. shpool attach test and then exit the session

Version info

shpool 0.9.3

Logs

Normal attaching with prompt_prefix = ""

2026-01-04T16:28:23.931445Z  INFO ThreadId(01) run:serve: socket got a new connection
2026-01-04T16:28:23.931848Z  INFO ThreadId(1184) handle_conn{cid=513}: new
2026-01-04T16:28:23.931878Z  INFO ThreadId(1184) handle_conn{cid=513}: broken pipe while writing version, likely just a daemon presence probe
2026-01-04T16:28:23.931904Z  INFO ThreadId(1184) handle_conn{cid=513}: close time.busy=32.6µs time.idle=23.5µs
2026-01-04T16:28:23.931965Z  INFO ThreadId(01) run:serve: socket got a new connection
2026-01-04T16:28:23.932015Z  INFO ThreadId(1185) handle_conn{cid=514}: new
2026-01-04T16:28:23.932031Z  INFO ThreadId(1185) handle_conn{cid=514}:parse_connect_header: new
2026-01-04T16:28:23.932208Z  INFO ThreadId(1185) handle_conn{cid=514}:parse_connect_header: close time.busy=173µs time.idle=4.12µs
2026-01-04T16:28:23.932243Z  INFO ThreadId(1185) handle_conn{cid=514}:handle_attach: new
2026-01-04T16:28:23.932393Z  INFO ThreadId(1185) handle_conn{cid=514}:handle_attach:build_shell_env: new
2026-01-04T16:28:23.932413Z  INFO ThreadId(1185) handle_conn{cid=514}:handle_attach:build_shell_env: injecting TERM into shell Some("xterm-ghostty")
2026-01-04T16:28:23.932436Z  INFO ThreadId(1185) handle_conn{cid=514}:handle_attach:build_shell_env: close time.busy=28.4µs time.idle=14.8µs
2026-01-04T16:28:23.932441Z  INFO ThreadId(1185) handle_conn{cid=514}:handle_attach:1_lock(shells): new
2026-01-04T16:28:23.932444Z  INFO ThreadId(1185) handle_conn{cid=514}:handle_attach:1_lock(shells): no existing 'test' session, creating new one
2026-01-04T16:28:23.932448Z  INFO ThreadId(1185) handle_conn{cid=514}:handle_attach:1_lock(shells): creating new subshell
2026-01-04T16:28:23.932451Z  INFO ThreadId(1185) handle_conn{cid=514}:handle_attach:1_lock(shells):spawn_subshell: new
2026-01-04T16:28:23.932454Z  INFO ThreadId(1185) handle_conn{cid=514}:handle_attach:1_lock(shells):spawn_subshell: user_info=Info { default_shell: "/usr/bin/fish", home_dir: "/home/ec2-user", user: "ec2-user" }
2026-01-04T16:28:23.932461Z  INFO ThreadId(1185) handle_conn{cid=514}:handle_attach:1_lock(shells):spawn_subshell: spawning shell in '/home/ec2-user/code/dotfiles'
2026-01-04T16:28:23.932755Z  INFO ThreadId(1185) handle_conn{cid=514}:handle_attach:1_lock(shells):spawn_subshell: about to fork subshell noecho=false
2026-01-04T16:28:23.936154Z  INFO ThreadId(1185) handle_conn{cid=514}:handle_attach:1_lock(shells):spawn_subshell: injecting prompt prefix
2026-01-04T16:28:23.936196Z  INFO ThreadId(1185) handle_conn{cid=514}:handle_attach:1_lock(shells):spawn_subshell:maybe_inject_prefix: new
2026-01-04T16:28:23.936204Z  INFO ThreadId(1185) handle_conn{cid=514}:handle_attach:1_lock(shells):spawn_subshell:maybe_inject_prefix: close time.busy=730ns time.idle=9.96µs
2026-01-04T16:28:23.936229Z  INFO ThreadId(1185) handle_conn{cid=514}:handle_attach:1_lock(shells):spawn_subshell:spawn_shell_to_client{s="test"}: new
2026-01-04T16:28:23.936336Z  INFO ThreadId(1185) handle_conn{cid=514}:handle_attach:1_lock(shells):spawn_subshell:spawn_shell_to_client{s="test"}: close time.busy=104µs time.idle=3.75µs
2026-01-04T16:28:23.936351Z  INFO ThreadId(1185) handle_conn{cid=514}:handle_attach:1_lock(shells):spawn_subshell: close time.busy=3.90ms time.idle=3.53µs
2026-01-04T16:28:23.936363Z  INFO ThreadId(1185) handle_conn{cid=514}:handle_attach:1_lock(shells): close time.busy=3.92ms time.idle=2.91µs
2026-01-04T16:28:23.936367Z  INFO ThreadId(1185) handle_conn{cid=514}:handle_attach: released lock on shells table
2026-01-04T16:28:23.936370Z  INFO ThreadId(1185) handle_conn{cid=514}:handle_attach:link_ssh_auth_sock: new
2026-01-04T16:28:23.936373Z  INFO ThreadId(1185) handle_conn{cid=514}:handle_attach:link_ssh_auth_sock: no SSH_AUTH_SOCK in client env, leaving it unlinked
2026-01-04T16:28:23.936377Z  INFO ThreadId(1185) handle_conn{cid=514}:handle_attach:link_ssh_auth_sock: close time.busy=4.24µs time.idle=2.84µs
2026-01-04T16:28:23.936381Z  INFO ThreadId(1185) handle_conn{cid=514}:handle_attach:populate_session_env_file: new
2026-01-04T16:28:23.936401Z  INFO ThreadId(1185) handle_conn{cid=514}:handle_attach:populate_session_env_file: populating "/run/user/1000/shpool/sessions/test/forward.env"
2026-01-04T16:28:23.936437Z  INFO ThreadId(1185) handle_conn{cid=514}:handle_attach:populate_session_env_file: close time.busy=53.4µs time.idle=2.95µs
2026-01-04T16:28:23.936442Z  INFO ThreadId(1185) handle_conn{cid=514}:handle_attach:write_reply: new
2026-01-04T16:28:23.936506Z  INFO ThreadId(1186) child_watcher{s="test" cid=514}: new
2026-01-04T16:28:23.936656Z  INFO ThreadId(1187) shell->client{s="test" cid=514}: new
2026-01-04T16:28:23.936696Z  INFO ThreadId(1185) handle_conn{cid=514}:handle_attach:write_reply: close time.busy=251µs time.idle=3.60µs
2026-01-04T16:28:23.936707Z  INFO ThreadId(1185) handle_conn{cid=514}:handle_attach: starting bidi stream loop
2026-01-04T16:28:23.936711Z  INFO ThreadId(1185) handle_conn{cid=514}:handle_attach:bidi_stream{s="test"}: new
2026-01-04T16:28:23.936722Z  INFO ThreadId(1185) handle_conn{cid=514}:handle_attach:bidi_stream{s="test"}:initial_attach_lock(shell_to_client_ctl): new
2026-01-04T16:28:23.937990Z  INFO ThreadId(1187) shell->client{s="test" cid=514}: waiting for initial client connection
2026-01-04T16:28:23.938220Z  INFO ThreadId(1185) handle_conn{cid=514}:handle_attach:bidi_stream{s="test"}:initial_attach_lock(shell_to_client_ctl): client connection status=New
2026-01-04T16:28:23.938313Z  INFO ThreadId(1187) shell->client{s="test" cid=514}: got initial client connection
2026-01-04T16:28:23.938374Z  INFO ThreadId(1187) shell->client{s="test" cid=514}: resized fd (rows=61, cols=209)
2026-01-04T16:28:23.938416Z  INFO ThreadId(1185) handle_conn{cid=514}:handle_attach:bidi_stream{s="test"}:initial_attach_lock(shell_to_client_ctl): close time.busy=1.69ms time.idle=4.50µs
2026-01-04T16:28:23.938493Z  INFO ThreadId(1185) handle_conn{cid=514}:handle_attach:bidi_stream{s="test"}:spawn_client_to_shell: new
2026-01-04T16:28:23.938615Z  INFO ThreadId(1185) handle_conn{cid=514}:handle_attach:bidi_stream{s="test"}:spawn_client_to_shell: close time.busy=79.6µs time.idle=42.8µs
2026-01-04T16:28:23.938676Z  INFO ThreadId(1185) handle_conn{cid=514}:handle_attach:bidi_stream{s="test"}:spawn_heartbeat: new
2026-01-04T16:28:23.938750Z  INFO ThreadId(1185) handle_conn{cid=514}:handle_attach:bidi_stream{s="test"}:spawn_heartbeat: close time.busy=25.0µs time.idle=49.0µs
2026-01-04T16:28:23.938864Z  INFO ThreadId(1185) handle_conn{cid=514}:handle_attach:bidi_stream{s="test"}:spawn_supervisor: new
2026-01-04T16:28:23.938940Z  INFO ThreadId(1185) handle_conn{cid=514}:handle_attach:bidi_stream{s="test"}:spawn_supervisor: close time.busy=28.5µs time.idle=47.8µs
2026-01-04T16:28:23.938852Z  INFO ThreadId(1189) heartbeat{s="test" cid=514}: new
2026-01-04T16:28:23.938694Z  INFO ThreadId(1188) client->shell{s="test" cid=514}: new
2026-01-04T16:28:23.941168Z  INFO ThreadId(1190) supervisor{s="test" cid=514}: new

Slow attaching with prompt_prefix commented out

2026-01-04T16:28:37.980813Z  INFO ThreadId(01) run:serve: socket got a new connection
2026-01-04T16:28:37.980870Z  INFO ThreadId(01) run:serve: socket got a new connection
2026-01-04T16:28:37.980934Z  INFO ThreadId(1192) handle_conn{cid=516}: new
2026-01-04T16:28:37.981064Z  INFO ThreadId(1192) handle_conn{cid=516}:parse_connect_header: new
2026-01-04T16:28:37.981114Z  INFO ThreadId(1192) handle_conn{cid=516}:parse_connect_header: close time.busy=42.4µs time.idle=7.63µs
2026-01-04T16:28:37.981144Z  INFO ThreadId(1192) handle_conn{cid=516}:handle_attach: new
2026-01-04T16:28:37.981250Z  INFO ThreadId(1192) handle_conn{cid=516}:handle_attach:build_shell_env: new
2026-01-04T16:28:37.981262Z  INFO ThreadId(1192) handle_conn{cid=516}:handle_attach:build_shell_env: injecting TERM into shell Some("xterm-ghostty")
2026-01-04T16:28:37.981268Z  INFO ThreadId(1191) handle_conn{cid=515}: new
2026-01-04T16:28:37.981283Z  INFO ThreadId(1191) handle_conn{cid=515}: broken pipe while writing version, likely just a daemon presence probe
2026-01-04T16:28:37.981289Z  INFO ThreadId(1191) handle_conn{cid=515}: close time.busy=10.7µs time.idle=10.5µs
2026-01-04T16:28:37.981311Z  INFO ThreadId(1192) handle_conn{cid=516}:handle_attach:build_shell_env: close time.busy=53.8µs time.idle=7.53µs
2026-01-04T16:28:37.981318Z  INFO ThreadId(1192) handle_conn{cid=516}:handle_attach:1_lock(shells): new
2026-01-04T16:28:37.981322Z  INFO ThreadId(1192) handle_conn{cid=516}:handle_attach:1_lock(shells): no existing 'test' session, creating new one
2026-01-04T16:28:37.981326Z  INFO ThreadId(1192) handle_conn{cid=516}:handle_attach:1_lock(shells): creating new subshell
2026-01-04T16:28:37.981329Z  INFO ThreadId(1192) handle_conn{cid=516}:handle_attach:1_lock(shells):spawn_subshell: new
2026-01-04T16:28:37.981333Z  INFO ThreadId(1192) handle_conn{cid=516}:handle_attach:1_lock(shells):spawn_subshell: user_info=Info { default_shell: "/usr/bin/fish", home_dir: "/home/ec2-user", user: "ec2-user" }
2026-01-04T16:28:37.981339Z  INFO ThreadId(1192) handle_conn{cid=516}:handle_attach:1_lock(shells):spawn_subshell: spawning shell in '/home/ec2-user/code/dotfiles'
2026-01-04T16:28:37.981634Z  INFO ThreadId(1192) handle_conn{cid=516}:handle_attach:1_lock(shells):spawn_subshell: about to fork subshell noecho=false
2026-01-04T16:28:37.985027Z  INFO ThreadId(1192) handle_conn{cid=516}:handle_attach:1_lock(shells):spawn_subshell: injecting prompt prefix
2026-01-04T16:28:37.985077Z  INFO ThreadId(1192) handle_conn{cid=516}:handle_attach:1_lock(shells):spawn_subshell:maybe_inject_prefix: new
2026-01-04T16:28:37.985086Z  INFO ThreadId(1192) handle_conn{cid=516}:handle_attach:1_lock(shells):spawn_subshell:maybe_inject_prefix:wait_for_startup: new
2026-01-04T16:28:37.985162Z  INFO ThreadId(1193) child_watcher{s="test" cid=516}: new
2026-01-04T16:28:40.182090Z  INFO ThreadId(1192) handle_conn{cid=516}:handle_attach:1_lock(shells):spawn_subshell:maybe_inject_prefix:wait_for_startup: close time.busy=2.20s time.idle=7.97µs
2026-01-04T16:28:40.182460Z  INFO ThreadId(1192) handle_conn{cid=516}:handle_attach:1_lock(shells):spawn_subshell:maybe_inject_prefix:sniff_shell: new
2026-01-04T16:28:40.182541Z  INFO ThreadId(1192) handle_conn{cid=516}:handle_attach:1_lock(shells):spawn_subshell:maybe_inject_prefix:sniff_shell: shell_proc_name: fish
2026-01-04T16:28:40.182586Z  INFO ThreadId(1192) handle_conn{cid=516}:handle_attach:1_lock(shells):spawn_subshell:maybe_inject_prefix:sniff_shell: close time.busy=74.3µs time.idle=51.4µs
2026-01-04T16:28:40.182644Z  INFO ThreadId(1192) handle_conn{cid=516}:handle_attach:1_lock(shells):spawn_subshell:maybe_inject_prefix: close time.busy=2.20s time.idle=10.9µs
2026-01-04T16:28:40.182695Z  INFO ThreadId(1192) handle_conn{cid=516}:handle_attach:1_lock(shells):spawn_subshell:spawn_shell_to_client{s="test"}: new
2026-01-04T16:28:40.182786Z  INFO ThreadId(1192) handle_conn{cid=516}:handle_attach:1_lock(shells):spawn_subshell:spawn_shell_to_client{s="test"}: close time.busy=50.5µs time.idle=40.7µs
2026-01-04T16:28:40.182917Z  INFO ThreadId(1192) handle_conn{cid=516}:handle_attach:1_lock(shells):spawn_subshell: close time.busy=2.20s time.idle=3.64µs
2026-01-04T16:28:40.182931Z  INFO ThreadId(1192) handle_conn{cid=516}:handle_attach:1_lock(shells): close time.busy=2.20s time.idle=3.45µs
2026-01-04T16:28:40.182937Z  INFO ThreadId(1192) handle_conn{cid=516}:handle_attach: released lock on shells table
2026-01-04T16:28:40.182941Z  INFO ThreadId(1192) handle_conn{cid=516}:handle_attach:link_ssh_auth_sock: new
2026-01-04T16:28:40.182944Z  INFO ThreadId(1192) handle_conn{cid=516}:handle_attach:link_ssh_auth_sock: no SSH_AUTH_SOCK in client env, leaving it unlinked
2026-01-04T16:28:40.182948Z  INFO ThreadId(1192) handle_conn{cid=516}:handle_attach:link_ssh_auth_sock: close time.busy=3.83µs time.idle=3.08µs
2026-01-04T16:28:40.182951Z  INFO ThreadId(1192) handle_conn{cid=516}:handle_attach:populate_session_env_file: new
2026-01-04T16:28:40.182969Z  INFO ThreadId(1192) handle_conn{cid=516}:handle_attach:populate_session_env_file: populating "/run/user/1000/shpool/sessions/test/forward.env"
2026-01-04T16:28:40.183003Z  INFO ThreadId(1192) handle_conn{cid=516}:handle_attach:populate_session_env_file: close time.busy=49.1µs time.idle=3.00µs
2026-01-04T16:28:40.183010Z  INFO ThreadId(1192) handle_conn{cid=516}:handle_attach:write_reply: new
2026-01-04T16:28:40.183034Z  INFO ThreadId(1192) handle_conn{cid=516}:handle_attach:write_reply: close time.busy=21.0µs time.idle=3.17µs
2026-01-04T16:28:40.183039Z  INFO ThreadId(1192) handle_conn{cid=516}:handle_attach: starting bidi stream loop
2026-01-04T16:28:40.183043Z  INFO ThreadId(1192) handle_conn{cid=516}:handle_attach:bidi_stream{s="test"}: new
2026-01-04T16:28:40.183049Z  INFO ThreadId(1192) handle_conn{cid=516}:handle_attach:bidi_stream{s="test"}:initial_attach_lock(shell_to_client_ctl): new
2026-01-04T16:28:40.182897Z  INFO ThreadId(1194) shell->client{s="test" cid=516}: new
2026-01-04T16:28:40.184609Z  INFO ThreadId(1194) shell->client{s="test" cid=516}: waiting for initial client connection
2026-01-04T16:28:40.184715Z  INFO ThreadId(1192) handle_conn{cid=516}:handle_attach:bidi_stream{s="test"}:initial_attach_lock(shell_to_client_ctl): client connection status=New
2026-01-04T16:28:40.184759Z  INFO ThreadId(1194) shell->client{s="test" cid=516}: got initial client connection
2026-01-04T16:28:40.184794Z  INFO ThreadId(1194) shell->client{s="test" cid=516}: resized fd (rows=61, cols=209)
2026-01-04T16:28:40.184861Z  INFO ThreadId(1192) handle_conn{cid=516}:handle_attach:bidi_stream{s="test"}:initial_attach_lock(shell_to_client_ctl): close time.busy=1.81ms time.idle=3.76µs
2026-01-04T16:28:40.184914Z  INFO ThreadId(1192) handle_conn{cid=516}:handle_attach:bidi_stream{s="test"}:spawn_client_to_shell: new
2026-01-04T16:28:40.185065Z  INFO ThreadId(1195) client->shell{s="test" cid=516}: new
2026-01-04T16:28:40.185111Z  INFO ThreadId(1192) handle_conn{cid=516}:handle_attach:bidi_stream{s="test"}:spawn_client_to_shell: close time.busy=188µs time.idle=9.33µs
2026-01-04T16:28:40.185159Z  INFO ThreadId(1192) handle_conn{cid=516}:handle_attach:bidi_stream{s="test"}:spawn_heartbeat: new
2026-01-04T16:28:40.185235Z  INFO ThreadId(1192) handle_conn{cid=516}:handle_attach:bidi_stream{s="test"}:spawn_heartbeat: close time.busy=22.9µs time.idle=53.4µs
2026-01-04T16:28:40.185245Z  INFO ThreadId(1192) handle_conn{cid=516}:handle_attach:bidi_stream{s="test"}:spawn_supervisor: new
2026-01-04T16:28:40.185262Z  INFO ThreadId(1192) handle_conn{cid=516}:handle_attach:bidi_stream{s="test"}:spawn_supervisor: close time.busy=13.6µs time.idle=3.67µs
2026-01-04T16:28:40.185387Z  INFO ThreadId(1197) supervisor{s="test" cid=516}: new
2026-01-04T16:28:40.185398Z  INFO ThreadId(1196) heartbeat{s="test" cid=516}: new
2026-01-04T16:28:40.578798Z  INFO ThreadId(1194) shell->client{s="test" cid=516}: saw prompt sentinel

[ethanpailes]

As we can see from the log, the 3-second discontinuity is happening as shpool is waiting for your shell to finish starting up:

2026-01-04T16:28:37.985086Z  INFO ThreadId(1192) handle_conn{cid=516}:handle_attach:1_lock(shells):spawn_subshell:maybe_inject_prefix:wait_for_startup: new
2026-01-04T16:28:37.985162Z  INFO ThreadId(1193) child_watcher{s="test" cid=516}: new
2026-01-04T16:28:40.182090Z  INFO ThreadId(1192) handle_conn{cid=516}:handle_attach:1_lock(shells):spawn_subshell:maybe_inject_prefix:wait_for_startup: close time.busy=2.20s time.idle=7.97µs

this is likely due to slowness in your shell's startup scripts, and isn't really something that shpool can do anything about. I'm going to close as WAI. If you want to submit a section to the troubleshooking wiki page about this, that might help other people noticing simillar behavior.

[injust]

this is likely due to slowness in your shell's startup scripts

No, I don't think so. This problem only happens with shpool and only when prompt_prefix is non-empty (either unset or set to a non-empty string).

The prompt injection doesn't happen for shpool attach --cmd=..., so I can't profile using fish --profile-startup 😦

[injust]

I replaced /usr/bin/fish with a script that calls the actual fish binary with --profile-startup=foo. This actually breaks the prompt injection, but the slowdown still happens.

The profiles look basically identically with/without prompt_prefix. So I really don't think it's my shell startup causing the delay.