toolbox run is too slow

[JayDoubleu]

toolbox run date seems to always have at least 2s delay, there is more delay depending on a application being run.
It seems that toolbox always runs checks regardless of container already being running or not, is there a way to tweak this so it behaves a little bit more like podman exec ?

• OS: clean f33-silverblue install

$ date; toolbox run date
Fri 25 Dec 23:41:43 GMT 2020
Fri Dec 25 23:41:45 GMT 2020

$ date; toolbox --verbose run date
Fri 25 Dec 23:39:00 GMT 2020
DEBU Running as real user ID 1000                 
DEBU Resolved absolute path to the executable as /usr/bin/toolbox 
DEBU Running on a cgroups v2 host                 
DEBU Checking if /etc/subgid and /etc/subuid have entries for user jaydoubleu 
DEBU TOOLBOX_PATH is /usr/bin/toolbox             
DEBU Toolbox config directory is /var/home/jaydoubleu/.config/toolbox 
DEBU Current Podman version is 2.2.1              
DEBU Old Podman version is 2.2.1                  
DEBU Migration not needed: Podman version 2.2.1 is unchanged 
DEBU Resolving container and image names          
DEBU Container: ''                                
DEBU Image: ''                                    
DEBU Release: ''                                  
DEBU Resolved container and image names           
DEBU Container: 'fedora-toolbox-33'               
DEBU Image: 'fedora-toolbox:33'                   
DEBU Release: '33'                                
DEBU Checking if container fedora-toolbox-33 exists 
DEBU Inspecting mounts of container fedora-toolbox-33 
DEBU Starting container fedora-toolbox-33         
DEBU Inspecting entry point of container fedora-toolbox-33 
DEBU Entry point PID is a float64                 
DEBU Entry point of container fedora-toolbox-33 is toolbox (PID=3429) 
DEBU Waiting for container fedora-toolbox-33 to finish initializing 
DEBU Checking if initialization stamp /run/user/1000/toolbox/container-initialized-3429 exists 
DEBU Container fedora-toolbox-33 is initialized   
DEBU Looking for command date in container fedora-toolbox-33 
DEBU Checking if 'podman exec' supports disabling the detach keys 
DEBU 'podman exec' supports disabling the detach keys 
DEBU Creating list of environment variables to forward 
DEBU COLORTERM=truecolor                          
DEBU DBUS_SESSION_BUS_ADDRESS=unix:path=/run/user/1000/bus 
DEBU DBUS_SYSTEM_BUS_ADDRESS is unset             
DEBU DESKTOP_SESSION=gnome                        
DEBU DISPLAY=:0                                   
DEBU LANG=en_GB.UTF-8                             
DEBU SHELL=/bin/bash                              
DEBU SSH_AUTH_SOCK=/run/user/1000/keyring/ssh     
DEBU TERM=xterm-256color                          
DEBU TOOLBOX_PATH=/usr/bin/toolbox                
DEBU VTE_VERSION=6201                             
DEBU WAYLAND_DISPLAY=wayland-0                    
DEBU XAUTHORITY=/run/user/1000/.mutter-Xwaylandauth.ENFGW0 
DEBU XDG_CURRENT_DESKTOP=GNOME                    
DEBU XDG_DATA_DIRS=/var/home/jaydoubleu/.local/share/flatpak/exports/share:/var/lib/flatpak/exports/share:/usr/local/share:/usr/share 
DEBU XDG_MENU_PREFIX=gnome-                       
DEBU XDG_RUNTIME_DIR=/run/user/1000               
DEBU XDG_SEAT is unset                            
DEBU XDG_SESSION_DESKTOP=gnome                    
DEBU XDG_SESSION_ID is unset                      
DEBU XDG_SESSION_TYPE=wayland                     
DEBU XDG_VTNR is unset                            
DEBU Running in container fedora-toolbox-33:      
DEBU podman                                       
DEBU --log-level                                  
DEBU error                                        
DEBU exec                                         
DEBU --detach-keys                                
DEBU                                              
DEBU --interactive                                
DEBU --tty                                        
DEBU --user                                       
DEBU jaydoubleu                                   
DEBU --workdir                                    
DEBU /var/home/jaydoubleu/provision/packages      
DEBU --env=COLORTERM=truecolor                    
DEBU --env=DBUS_SESSION_BUS_ADDRESS=unix:path=/run/user/1000/bus 
DEBU --env=DESKTOP_SESSION=gnome                  
DEBU --env=DISPLAY=:0                             
DEBU --env=LANG=en_GB.UTF-8                       
DEBU --env=SHELL=/bin/bash                        
DEBU --env=SSH_AUTH_SOCK=/run/user/1000/keyring/ssh 
DEBU --env=TERM=xterm-256color                    
DEBU --env=TOOLBOX_PATH=/usr/bin/toolbox          
DEBU --env=VTE_VERSION=6201                       
DEBU --env=WAYLAND_DISPLAY=wayland-0              
DEBU --env=XAUTHORITY=/run/user/1000/.mutter-Xwaylandauth.ENFGW0 
DEBU --env=XDG_CURRENT_DESKTOP=GNOME              
DEBU --env=XDG_DATA_DIRS=/var/home/jaydoubleu/.local/share/flatpak/exports/share:/var/lib/flatpak/exports/share:/usr/local/share:/usr/share 
DEBU --env=XDG_MENU_PREFIX=gnome-                 
DEBU --env=XDG_RUNTIME_DIR=/run/user/1000         
DEBU --env=XDG_SESSION_DESKTOP=gnome              
DEBU --env=XDG_SESSION_TYPE=wayland               
DEBU fedora-toolbox-33                            
DEBU capsh                                        
DEBU --caps=                                      
DEBU --                                           
DEBU -c                                           
DEBU exec "$@"                                    
DEBU /bin/sh                                      
DEBU date                                         
Fri Dec 25 23:39:02 GMT 2020

Usually 2-6 seconds delay wouldn't be a big deal however I am trying to run some applications to avoid altering silverblue's core os and this is noticeable.

[changwuf31]

toolbox is running podman cli for checking stuff, each time a cli is executed, there is a 300 - 500ms latency.
I've been able to shave it to around 500 - 600ms for toolbox run if the container is already started, though I'm not sure if there is any side effect.

[debarshiray]

One problem is that that the enter and run commands invoke podman exec twice.

The second podman exec is used to check if the binary is actually present inside the container or not. Look for the isCommandPresent function.

This is caused by the inherent difficulty in figuring out the presence of the binary. podman exec uses an exit code of 127 if the binary you asked it to execute doesn't exist. However, if the binary is a shell, and inside that shell you tried to run something that doesn't exist, and quit immediately, then that will also cause podman exec to exit with 127.

I wonder if there's a smarter way to go about this.

[changwuf31]

One problem is that that the enter and run commands invoke podman exec twice.

The second podman exec is used to check if the binary is actually present inside the container or not. Look for the isCommandPresent function.

This is caused by the inherent difficulty in figuring out the presence of the binary. podman exec uses an exit code of 127 if the binary you asked it to execute doesn't exist. However, if the binary is a shell, and inside that shell you tried to run something that doesn't exist, and quit immediately, then that will also cause podman exec to exit with 127.

I wonder if there's a smarter way to go about this.

maybe we can just run podman exec, and if it errors, we fall back to /bin/bash ?

[JayDoubleu]

Is there a purpose to run all those checks once the container is up ?
Perhaps adding some flag --nocheck or --exec and allowing it to simply fire exec at the container?

[debarshiray]

maybe we can just run podman exec, and if it errors, we fall back
to /bin/bash ?

Umm... we likely can't because:

$ podman exec ... /bin/foo
...
$ echo $?
127
$ podman exec /bin/bash
> /bin/foo
bash: foo: command not found...
>
$ echo $?
127

(This is what I tried to explain in words, but it's a bit confusing.)

So, if we just checked for 127, then in the latter case Toolbox would spawn another instance of Bash after the first instance was quit.

[debarshiray]

I think one option is to shuffle the code around, so that we can examine the causes of podman exec returning with 127 by calling isCommandPresent after the failure. Like we do for isPathPresent.

[changwuf31]

I think one option is to shuffle the code around, so that we can examine the causes of podman exec returning with 127 by calling isCommandPresent after the failure. Like we do for isPathPresent.

What if we just let it error ? Just what if, this could also potentially solve #657 ?

[debarshiray]

I think one option is to shuffle the code around, so that we can
examine the causes of podman exec returning with 127 by
calling isCommandPresent after the failure. Like we do for
isPathPresent.

This was done in #813 (which requires the follow-up fix in #872).

We now attempt the non-fallback behaviour directly without doing any checks. If that fails, we invoke podman exec a few times to figure out the cause of the failure, whether it was due to the working directory being missing or the command, and try the relevant fallback behaviour depending on that.

This should have sped up toolbox enter for most users. ie., those that don't hit the fallback code paths.

What if we just let it error ?

I think we can't just it error out, because it would make things difficult for users who use a shell that's not present in the Toolbox image. eg., Z shell. In such cases, it's good to fallback to Bash inside the container, so that users have the chance to install their favourite shell.

[debarshiray]

I am going to close this now.

Please feel free to re-open this issue or file a new one, if you think that toolbox enter is still as slow as before or there's been a regression caused by this optimization.

[JayDoubleu]

Thanks @debarshiray it is indeed noticeably faster now.