From b34979d712fdecb858f1dad0231eb41152581aca Mon Sep 17 00:00:00 2001 From: Debarshi Ray Date: Mon, 20 May 2024 00:38:48 +0200 Subject: [PATCH] cmd/run: Optimize 'enter' and 'run' for a container getting initialized Currently, the 'enter' and 'run' commands poll at one second intervals to check if the Toolbx container's entry point has created the initialization stamp file to indicate that the container has been initialized. This came from the POSIX shell implementation [1], where it was relatively easier to poll than to use inotify(7) to monitor the file system. The problem with polling is that the interval is always going to be either too short and waste resources or too long and cause delays. The current one second interval is sufficiently long to add a noticeable delay to the 'enter' and 'run' commands. It will be better to use inotify(7) to monitor the file system, which is quite easy to do with the Go implementation, so that the commands can proceed as soon as the initialization stamp file is available, instead of waiting for the polling interval to pass. There's a fallback to polling, as before, when the operating system is suffering from a shortage of resources needed for inotify(7). This code path can be forced through the TOOLBOX_RUN_USE_POLLING environment variable for testing. [1] Commit d3e0f3df06d3f5ac https://github.com/containers/toolbox/commit/d3e0f3df06d3f5ac https://github.com/containers/toolbox/pull/305 https://github.com/containers/toolbox/issues/1070 --- src/cmd/run.go | 157 ++++++++++++++++++++++++++++++++++++++++++++----- 1 file changed, 142 insertions(+), 15 deletions(-) diff --git a/src/cmd/run.go b/src/cmd/run.go index c67608f35..a7f776a8e 100644 --- a/src/cmd/run.go +++ b/src/cmd/run.go @@ -21,6 +21,7 @@ import ( "fmt" "io" "os" + "strconv" "strings" "time" @@ -28,8 +29,10 @@ import ( "github.com/containers/toolbox/pkg/shell" "github.com/containers/toolbox/pkg/term" "github.com/containers/toolbox/pkg/utils" + "github.com/fsnotify/fsnotify" "github.com/sirupsen/logrus" "github.com/spf13/cobra" + "golang.org/x/sys/unix" ) var ( @@ -282,24 +285,10 @@ func runCommand(container string, logrus.Debugf("Waiting for container %s to finish initializing", container) } - toolboxRuntimeDirectory, err := utils.GetRuntimeDirectory(currentUser) - if err != nil { + if err := ensureContainerIsInitialized(container, entryPointPID); err != nil { return err } - initializedStamp := fmt.Sprintf("%s/container-initialized-%d", toolboxRuntimeDirectory, entryPointPID) - - logrus.Debugf("Checking if initialization stamp %s exists", initializedStamp) - - initializedTimeout := 25 // seconds - for i := 0; !utils.PathExists(initializedStamp); i++ { - if i == initializedTimeout { - return fmt.Errorf("failed to initialize container %s", container) - } - - time.Sleep(time.Second) - } - logrus.Debugf("Container %s is initialized", container) if err := runCommandWithFallbacks(container, @@ -534,6 +523,131 @@ func constructExecArgs(container, preserveFDs string, return execArgs } +func ensureContainerIsInitialized(container string, entryPointPID int) error { + toolboxRuntimeDirectory, err := utils.GetRuntimeDirectory(currentUser) + if err != nil { + return err + } + + initializedStamp := fmt.Sprintf("%s/container-initialized-%d", toolboxRuntimeDirectory, entryPointPID) + logrus.Debugf("Checking if initialization stamp %s exists", initializedStamp) + + // Optional shortcut for containers that are already initialized + if utils.PathExists(initializedStamp) { + return nil + } + + logrus.Debugf("Setting up initialization timeout for container %s", container) + initializedTimeout := time.NewTimer(25 * time.Second) + defer initializedTimeout.Stop() + + var usePolling bool + if shouldUsePolling() { + usePolling = true + } + + var watcherForStamp *fsnotify.Watcher + + if !usePolling { + logrus.Debugf("Setting up watches for file system events from container %s", container) + + var err error + watcherForStamp, err = fsnotify.NewWatcher() + if err != nil { + if errors.Is(err, unix.EMFILE) || errors.Is(err, unix.ENFILE) || errors.Is(err, unix.ENOMEM) { + logrus.Debugf("Setting up watches for file system events: failed to create Watcher: %s", + err) + logrus.Debug("Using polling instead") + usePolling = true + } else { + return fmt.Errorf("failed to create Watcher: %w", err) + } + } + } + + var watcherForStampErrors chan error + var watcherForStampEvents chan fsnotify.Event + + if watcherForStamp != nil { + defer watcherForStamp.Close() + + if err := watcherForStamp.Add(toolboxRuntimeDirectory); err != nil { + if errors.Is(err, unix.ENOMEM) || errors.Is(err, unix.ENOSPC) { + logrus.Debugf("Setting up watches for file system events: failed to add path: %s", err) + logrus.Debug("Using polling instead") + usePolling = true + } else { + return fmt.Errorf("failed to add path to Watcher: %w", err) + } + } + + if !usePolling { + watcherForStampErrors = watcherForStamp.Errors + watcherForStampEvents = watcherForStamp.Events + } + } + + var tickerPolling *time.Ticker + var tickerPollingCh <-chan time.Time + + if usePolling { + logrus.Debugf("Setting up polling ticker for container %s", container) + + tickerPolling = time.NewTicker(time.Second) + defer tickerPolling.Stop() + + tickerPollingCh = tickerPolling.C + } + + // Initialization could have finished before the Watcher was set up + if utils.PathExists(initializedStamp) { + return nil + } + + logrus.Debug("Listening to file system, ticker and timeout events") + + for { + select { + case <-initializedTimeout.C: + return fmt.Errorf("failed to initialize container %s", container) + case time := <-tickerPollingCh: + if done := handlePollingTickForStamp(time, initializedStamp); done { + return nil + } + case event := <-watcherForStampEvents: + if done := handleFileSystemEventForStamp(event, initializedStamp); done { + return nil + } + case err := <-watcherForStampErrors: + logrus.Debugf("Received an error from the file system watcher: %s", err) + } + } + + // code should not be reached +} + +func handleFileSystemEventForStamp(event fsnotify.Event, initializedStamp string) bool { + eventOpString := event.Op.String() + logrus.Debugf("Handling file system event: operation %s on %s", eventOpString, event.Name) + + if event.Name == initializedStamp && utils.PathExists(initializedStamp) { + return true + } + + return false +} + +func handlePollingTickForStamp(time time.Time, initializedStamp string) bool { + timeString := time.String() + logrus.Debugf("Handling polling tick %s", timeString) + + if utils.PathExists(initializedStamp) { + return true + } + + return false +} + func isCommandPresent(container, command string) (bool, error) { logrus.Debugf("Looking up command %s in container %s", command, container) @@ -572,6 +686,19 @@ func isPathPresent(container, path string) (bool, error) { return true, nil } +func shouldUsePolling() bool { + valueString := os.Getenv("TOOLBOX_RUN_USE_POLLING") + if valueString == "" { + return false + } + + if valueBool, err := strconv.ParseBool(valueString); err == nil { + return valueBool + } + + return true +} + func startContainer(container string) error { var stderr strings.Builder if err := podman.Start(container, &stderr); err == nil {