Repository navigation
Performance regression on every command invocation #3621
Description
cbec75e2f3f5afd3334db693829a6b150612076c is the first bad commit
commit cbec75e2f3f5afd3334db693829a6b150612076c
Author: Nicolas De Loof <nicolas.deloof@gmail.com>
Date: Wed Mar 30 15:27:25 2022 +0200
Adopt Cobra completion v2 to support completion by CLI plugins
Signed-off-by: Nicolas De Loof <nicolas.deloof@gmail.com>
cli-plugins/manager/cobra.go | 48 +++++++++++++++---
cli-plugins/plugin/plugin.go | 5 ++
...
After #3429 every command invocation takes ~200ms longer. Even when command just redirects to another process.
Before:
# time /tmp/docker buildx version
github.com/docker/buildx v0.8.0-92-g908ce2d2.m 908ce2d20618a069ddd06fc4f044505899932fe2.m
/tmp/docker buildx version 0.06s user 0.04s system 98% cpu 0.098 total
# time /tmp/docker buildx version
github.com/docker/buildx v0.8.0-92-g908ce2d2.m 908ce2d20618a069ddd06fc4f044505899932fe2.m
/tmp/docker buildx version 0.06s user 0.03s system 99% cpu 0.095 total
# time /tmp/docker buildx version
github.com/docker/buildx v0.8.0-92-g908ce2d2.m 908ce2d20618a069ddd06fc4f044505899932fe2.m
/tmp/docker buildx version 0.06s user 0.03s system 94% cpu 0.096 total
# time /tmp/docker --version
Docker version unknown-version, build unknown-commit
/tmp/docker --version 0.02s user 0.01s system 71% cpu 0.038 total
# time /tmp/docker --version
Docker version unknown-version, build unknown-commit
/tmp/docker --version 0.02s user 0.01s system 70% cpu 0.036 total
After:
github.com/docker/buildx v0.8.0-92-g908ce2d2.m 908ce2d20618a069ddd06fc4f044505899932fe2.m
/tmp/docker buildx version 0.19s user 0.10s system 89% cpu 0.322 total
# time /tmp/docker buildx version
github.com/docker/buildx v0.8.0-92-g908ce2d2.m 908ce2d20618a069ddd06fc4f044505899932fe2.m
/tmp/docker buildx version 0.19s user 0.10s system 90% cpu 0.325 total
# time /tmp/docker buildx version
github.com/docker/buildx v0.8.0-92-g908ce2d2.m 908ce2d20618a069ddd06fc4f044505899932fe2.m
/tmp/docker buildx version 0.18s user 0.10s system 90% cpu 0.312 total
# time /tmp/docker --version
Docker version unknown-version, build unknown-commit
/tmp/docker --version 0.16s user 0.09s system 89% cpu 0.280 total
# time /tmp/docker --version
Docker version unknown-version, build unknown-commit
/tmp/docker --version 0.16s user 0.09s system 89% cpu 0.272 total
Reacted by CrazyMax
Activity
thaJeztah commentedon May 19, 2022
Copying some details from a slack conversation;
From @tonistiigi
Basic outline of time spent on CLI redirect(not compose-cli that adds another 100ms):
Sometimes initial binary call(either for docker or plugin) is +100ms. Looks like some macos system cache.
Client ping is not needed and could be avoided. Metadata() call could be cached with some refactoring as no need to check every time.
The client ping is quick so not necessarily saying the optimization is worth it. all commands except redirect and --version would actually use this result so would need to run it anyway then. avoiding extra metadata call could be nice though
Regarding the "metadata";
@thaJeztah: the plug-in election / discovery is going through several directories, and executing each plugin to get the metadata; I recall discussing caching the results with Ian when he was implementing it (we probably should) could be a short TTL for the cache (short being relative; could even be "minutes"
@tonistiigi: we could cache the inode+size of the plugin after we have called metadata on it once. next time would just do a stat call and skip metadata if the plugin file has not changed
@thaJeztah: Good idea yes. We'd still need to (periodically) scan if new plugins were installed, or if a plugin was installed in a path with a higher priority, but perhaps that in itself isn't the bottleneck (although it depends on how many files are in those directories I guess)
@tonistiigi: This already gets called on a specific plugin so new ones would still first get the uncached part. the stat calls that look up the plugin from the list of paths should be fast enough and don’t need to be cached.
crazy-max commentedon May 30, 2022
Also encountered this issue with
docker version --format "{{.Client.Version}}":thaJeztah commentedon May 30, 2022
@crazy-max do you think it'd be possible to run a git bisect with that information? (guess that might be tricky as "time taken" may not be an easy one to bisect; perhaps possible though with the right threshold 🤔
crazy-max commentedon May 30, 2022
Here is a quick bench:
Note the regression after 84b86e2 linked to #3429
crazy-max commentedon Jun 21, 2022
Not tested but I wonder if completion perf regression being fixed in cobra 1.5.0 could fix this issue: https://github.com/spf13/cobra/releases/tag/v1.5.0
thaJeztah commentedon Jan 12, 2023
This still needs to be looked into. I just compared (note: on different machines, so not a "straight" compare) between 23.0.0 and 20.10;
On 20.10:
On 23.0.0:
Notice that
--versionalso shows the issue, which should help debugging; this PR may be useful as a starting point; I recall when I was working on that PR that there's other code-paths that may be loading / checking for plugins (even though those results may not be needed at that point);tonistiigi commentedon Feb 2, 2023
Results from hyperfine
20.10.23
23.0.0
crazy-max commentedon Mar 24, 2023
Updated bench results using hyperfine: https://github.com/crazy-max/docker-cli-bench/blob/main/bench.md
crazy-max commentedon Mar 25, 2023
Opened several PRs with different approaches to fix this issue: