Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

git: starship still unusable in git repos (with submodules?) #4275

Closed
matthiaskrgr opened this issue Aug 17, 2022 · 18 comments · Fixed by #4281
Closed

git: starship still unusable in git repos (with submodules?) #4275

matthiaskrgr opened this issue Aug 17, 2022 · 18 comments · Fixed by #4281
Labels
🐛 bug Something isn't working as expected.

Comments

@matthiaskrgr
Copy link

Bug Report

It looks like the point-release solved the hang in git repos, but starship still takes ~5 seconds to load inside a rust-lang/rust repository for me rendering it unusable. It used to take less than a second to load before 1.10.

Possible Solution

Can probably disable the git functionality or downgrade.

Environment

  • Starship version: [the output of starship --version]
starship 1.10.1
branch:
commit_hash:
build_time:2022-08-16 00:27:55 +02:00
build_env:rustc 1.65.0-nightly (801821d15 2022-08-14),nightly-x86_64-unknown-linux-gnu
  • Shell type: zsh 5.9
  • Terminal emulator: alacritty
  • Operating system: manjaro linux

Relevant Shell Configuration

# Your configuration here

Starship Configuration

# Inserts a blank line between shell prompts
add_newline = false

[time]
disabled = false

[status]
disabled = true

[cmd_duration]
min_time = 100

[directory]
truncate_to_repo = false
truncation_length = 20
@matthiaskrgr matthiaskrgr added the 🐛 bug Something isn't working as expected. label Aug 17, 2022
@matthiaskrgr
Copy link
Author

Since starship is still snappy in other big repos like widelands, wesnoth or llvm-project, I assume this is some corner-case related to rust-langs submodules? 🤔

@matthiaskrgr matthiaskrgr changed the title git: starship still unusable in git repos git: starship still unusable in git repos (with submodules?) Aug 17, 2022
@andytom
Copy link
Member

andytom commented Aug 17, 2022

Hey @matthiaskrgr, there is a bug with submodules, #4266, but not sure if that is the same issue you are having here.

@matthiaskrgr
Copy link
Author

Hm, right, when I am inside a repo that has a submodule (but not inside the submodule itself), it shows correct hash but wrong tag 🤔

@davidkna
Copy link
Member

davidkna commented Aug 17, 2022

I can't confirm the issue in my local copy of the rust repo as-is.

I assume the suggested workaround for #4251, setting export STARSHIP_NUM_THREADS=6 doesn't have any impact? Is there any specific git module experiencing the slowdown (try starship timings)? Please also post the output of STARSHIP_LOG=trace starship prompt.

@davidkna
Copy link
Member

@matthiaskrgr And just to confirm: Do you also get the issue if you compile starship with a stable rust toolchain?

@Byron
Copy link
Contributor

Byron commented Aug 17, 2022

Timings for me look like this with #4277 applied (even though I don't think the patch is related):

 Here are the timings of modules in your prompt (>=1ms or output):
 git_status   -  387ms  -   "�[1;31m[!]�[0m "
 git_metrics  -  298ms  -   "�[1;32m+8�[0m �[1;31m-8�[0m "
 directory    -   <1ms  -   "�[1;36mrust�[0m "
 git_branch   -   <1ms  -   "�[1;35m( master)�[0m "
 python       -   <1ms  -   "via �[1;33m🐍 �[0m"
 line_break   -   <1ms  -   "\n"
 character    -   <1ms  -   "�[1;32m❯�[0m "

Neither git_status nor git_metrics are using gitoxide yet (and when they do, I think they can both share a lot of the required runtime).

Thus I am also curious about your timings to see where all the time is spent.

@matthiaskrgr
Copy link
Author

export STARSHIP_NUM_THREADS=6 doesnt seem to make much of an impact, but it also doesn't look like the "hang" is a multithreaded workload.

starship timings:

 Here are the timings of modules in your prompt (>=1ms or output):
 git_commit  -  3991ms  -   "(1199dbd 🏷  1.0.0-beta) "
 git_status  -   506ms  -   ""
 directory   -    21ms  -   "~/vcs/github/rust "
 rust        -    21ms  -   "via 🦀 v1.65.0-nightly "
 python      -     5ms  -   "via 🐍 v3.10.5 "
 line_break  -    <1ms  -   "\n"
 time        -    <1ms  -   "at 17:03:23 "
 character   -    <1ms  -   "❯ "

STARSHIP_LOG=trace starship prompt

[TRACE] - (starship): Parsed arguments: Cli {
   command: Prompt {
       right: false,
       continuation: false,
       properties: Properties {
           status_code: None,
           pipestatus: None,
           terminal_width: 317,
           path: None,
           logical_path: None,
           cmd_duration: None,
           keymap: "viins",
           jobs: 0,
       },
   },
}
[DEBUG] - (starship::config): STARSHIP_CONFIG is not set
[DEBUG] - (starship::config): Using default config path: /home/matthias/.config/starship.toml
[TRACE] - (starship::utils): Trying to read from "/home/matthias/.config/starship.toml"
[TRACE] - (starship::utils): File read successfully
[TRACE] - (starship::config): Config file content: "
# Inserts a blank line between shell prompts
add_newline = false

[time]
disabled = false

[status]
disabled = true

[cmd_duration]
min_time = 100

[directory]
truncate_to_repo = false
truncation_length = 20
"
[DEBUG] - (starship::config): Config parsed: Table({"add_newline": Boolean(false), "time": Table({"disabled": Boolean(false)}), "status": Table({"disabled": Boolean(true)}), "cmd_duration": Table({"min_time": Integer(100)}), "directory": Table({"truncate_to_repo": Boolean(false), "truncation_length": Integer(20)})})
[TRACE] - (starship::context): Received completed pipestatus of None
[TRACE] - (starship::config): No config found for "username": Option "username" not found
[TRACE] - (starship::config): No config found for "spack": Option "spack" not found
[TRACE] - (starship::config): No config found for "username": Option "username" not found
[TRACE] - (starship::modules): Took 1.273547ms to compute module "username"
[TRACE] - (starship::config): No config found for "username": Option "username" not found
[TRACE] - (starship::config): No config found for "hostname": Option "hostname" not found
[TRACE] - (starship::config): No config found for "hostname": Option "hostname" not found
[TRACE] - (starship::modules): Took 455.368µs to compute module "hostname"
[TRACE] - (starship::config): No config found for "localip": Option "localip" not found
[TRACE] - (starship::config): No config found for "localip": Option "localip" not found
[TRACE] - (starship::modules): Took 244.841µs to compute module "localip"
[TRACE] - (starship::config): No config found for "perl": Option "perl" not found
[TRACE] - (starship::config): No config found for "perl": Option "perl" not found
[TRACE] - (starship::context): Building HashSets of directory files, folders and extensions took 1.934309ms
[TRACE] - (starship::modules): Took 2.289026ms to compute module "perl"
[TRACE] - (starship::config): No config found for "perl": Option "perl" not found
[TRACE] - (starship::config): No config found for "php": Option "php" not found
[TRACE] - (starship::config): No config found for "php": Option "php" not found
[TRACE] - (starship::modules): Took 131.716µs to compute module "php"
[TRACE] - (starship::config): No config found for "pulumi": Option "pulumi" not found
[TRACE] - (starship::config): No config found for "pulumi": Option "pulumi" not found
[TRACE] - (starship::modules::pulumi): Looking for package file in "/home/matthias/vcs/github/rust"
[TRACE] - (starship::modules::pulumi): Looking for package file in "/home/matthias/vcs/github"
[TRACE] - (starship::modules::pulumi): Looking for package file in "/home/matthias/vcs"
[TRACE] - (starship::modules::pulumi): Looking for package file in "/home/matthias"
[TRACE] - (starship::modules::pulumi): Looking for package file in "/home"
[TRACE] - (starship::modules::pulumi): Looking for package file in "/"
[TRACE] - (starship::modules::pulumi): Did not find a Pulumi package file
[TRACE] - (starship::modules): Took 8.077811ms to compute module "pulumi"
[TRACE] - (starship::config): No config found for "pulumi": Option "pulumi" not found
[TRACE] - (starship::config): No config found for "purescript": Option "purescript" not found
[TRACE] - (starship::config): No config found for "purescript": Option "purescript" not found
[TRACE] - (starship::modules): Took 209.603µs to compute module "purescript"
[TRACE] - (starship::config): No config found for "python": Option "python" not found
[TRACE] - (starship::config): No config found for "python": Option "python" not found
[TRACE] - (starship::context): Executing command "python" with args ["--version"] from context
[TRACE] - (starship::utils): Creating Command for binary "python"
[TRACE] - (starship::utils): Using "/usr/bin/python" as "python"
[TRACE] - (starship::modules): Took 141.097µs to compute module "spack"
[TRACE] - (starship::config): No config found for "shlvl": Option "shlvl" not found
[TRACE] - (starship::config): No config found for "shlvl": Option "shlvl" not found
[TRACE] - (starship::modules): Took 466.456µs to compute module "shlvl"
[TRACE] - (starship::config): No config found for "singularity": Option "singularity" not found
[TRACE] - (starship::modules): Took 5.025µs to compute module "singularity"
[TRACE] - (starship::config): No config found for "kubernetes": Option "kubernetes" not found
[TRACE] - (starship::config): No config found for "kubernetes": Option "kubernetes" not found
[TRACE] - (starship::modules): Took 436.114µs to compute module "kubernetes"
[DEBUG] - (starship::config): Config found for "directory": Some(Table({"truncate_to_repo": Boolean(false), "truncation_length": Integer(20)}))
[DEBUG] - (starship::config): Config found for "directory": Some(Table({"truncate_to_repo": Boolean(false), "truncation_length": Integer(20)}))
[DEBUG] - (starship::modules::directory): Home dir: "/home/matthias"
[DEBUG] - (starship::modules::directory): Physical dir: "/home/matthias/vcs/github/rust"
[DEBUG] - (starship::modules::directory): Display dir: "/home/matthias/vcs/github/rust"
[TRACE] - (starship::config): No config found for "memory_usage": Option "memory_usage" not found
[TRACE] - (starship::config): No config found for "memory_usage": Option "memory_usage" not found
[TRACE] - (starship::modules): Took 449.063µs to compute module "memory_usage"
[TRACE] - (starship::config): No config found for "rust": Option "rust" not found
[TRACE] - (starship::config): No config found for "rust": Option "rust" not found
[TRACE] - (starship::modules::rust): Searching for rustup toolchain in environment.
[TRACE] - (starship::modules::rust): Searching for toolchain in toolchain file
[DEBUG] - (starship::modules::rust): Environmental toolchain override is Some("nightly-x86_64-unknown-linux-gnu")
[TRACE] - (starship::modules::rust): Running rustc --version directly with "/home/matthias/.rustup/toolchains/nightly-x86_64-unknown-linux-gnu/bin/rustc"
[TRACE] - (starship::utils): Creating Command for binary "/home/matthias/.rustup/toolchains/nightly-x86_64-unknown-linux-gnu/bin/rustc"
[TRACE] - (starship::utils): Using "/home/matthias/.rustup/toolchains/nightly-x86_64-unknown-linux-gnu/bin/rustc" as "/home/matthias/.rustup/toolchains/nightly-x86_64-unknown-linux-gnu/bin/rustc"
[TRACE] - (starship::config): No config found for "aws": Option "aws" not found
[TRACE] - (starship::config): No config found for "aws": Option "aws" not found
[TRACE] - (starship::modules): Took 180.789µs to compute module "aws"
[TRACE] - (starship::config): No config found for "gcloud": Option "gcloud" not found
[TRACE] - (starship::config): No config found for "gcloud": Option "gcloud" not found
[TRACE] - (starship::utils): Trying to read from "/home/matthias/.config/gcloud/active_config"
[DEBUG] - (starship::utils): Error reading file: Err(Os { code: 2, kind: NotFound, message: "No such file or directory" })
[TRACE] - (starship::modules): Took 737.099µs to compute module "gcloud"
[TRACE] - (starship::config): No config found for "openstack": Option "openstack" not found
[TRACE] - (starship::config): No config found for "openstack": Option "openstack" not found
[TRACE] - (starship::modules): Took 116.088µs to compute module "openstack"
[TRACE] - (starship::config): No config found for "azure": Option "azure" not found
[TRACE] - (starship::config): No config found for "azure": Option "azure" not found
[TRACE] - (starship::modules): Took 95.523µs to compute module "azure"
[TRACE] - (starship::config): No config found for "env_var": Option "env_var" not found
[TRACE] - (starship::config): No config found for "env_var": Option "env_var" not found
[TRACE] - (starship::modules): Took 116.456µs to compute module "env_var"
[TRACE] - (starship::config): No config found for "crystal": Option "crystal" not found
[TRACE] - (starship::config): No config found for "crystal": Option "crystal" not found
[TRACE] - (starship::modules): Took 100.627µs to compute module "crystal"
[TRACE] - (starship::config): No config found for "custom": Option "custom" not found
[TRACE] - (starship::config): No config found for "sudo": Option "sudo" not found
[TRACE] - (starship::config): No config found for "sudo": Option "sudo" not found
[TRACE] - (starship::modules): Took 78.219µs to compute module "sudo"
[DEBUG] - (starship::config): Config found for "cmd_duration": Some(Table({"min_time": Integer(100)}))
[DEBUG] - (starship::config): Config found for "cmd_duration": Some(Table({"min_time": Integer(100)}))
[TRACE] - (starship::modules): Took 150.372µs to compute module "cmd_duration"
[TRACE] - (starship::config): No config found for "line_break": Option "line_break" not found
[TRACE] - (starship::config): No config found for "line_break": Option "line_break" not found
[TRACE] - (starship::modules): Took 78.413µs to compute module "line_break"
[TRACE] - (starship::config): No config found for "jobs": Option "jobs" not found
[TRACE] - (starship::config): No config found for "jobs": Option "jobs" not found
[TRACE] - (starship::modules): Took 72.126µs to compute module "jobs"
[TRACE] - (starship::config): No config found for "battery": Option "battery" not found
[TRACE] - (starship::modules): Took 158.51µs to compute module "battery"
[DEBUG] - (starship::config): Config found for "time": Some(Table({"disabled": Boolean(false)}))
[DEBUG] - (starship::config): Config found for "time": Some(Table({"disabled": Boolean(false)}))
[TRACE] - (starship::modules::time): Timer module is enabled with format string: %T
[TRACE] - (starship::config): Parsing color_string: yellow
[TRACE] - (starship::config): Read predefined color: yellow
[TRACE] - (starship::modules): Took 6.649105ms to compute module "time"
[DEBUG] - (starship::config): Config found for "status": Some(Table({"disabled": Boolean(true)}))
[TRACE] - (starship::config): No config found for "container": Option "container" not found
[TRACE] - (starship::config): No config found for "container": Option "container" not found
[TRACE] - (starship::modules): Took 226.395µs to compute module "container"
[TRACE] - (starship::config): No config found for "shell": Option "shell" not found
[TRACE] - (starship::config): No config found for "shell": Option "shell" not found
[TRACE] - (starship::modules): Took 178.629µs to compute module "shell"
[TRACE] - (starship::config): No config found for "character": Option "character" not found
[TRACE] - (starship::config): No config found for "character": Option "character" not found
[TRACE] - (starship::config): Parsing color_string: green
[TRACE] - (starship::config): Read predefined color: green
[TRACE] - (starship::modules): Took 356.581µs to compute module "character"
[TRACE] - (starship::config): No config found for "vagrant": Option "vagrant" not found
[TRACE] - (starship::utils): stdout: "Python 3.10.5\n", stderr: "", exit code: "Some(0)", took 39.483171ms
[TRACE] - (starship::config): No config found for "vagrant": Option "vagrant" not found
[TRACE] - (starship::modules): Took 142.891µs to compute module "vagrant"
[TRACE] - (starship::config): No config found for "zig": Option "zig" not found
[TRACE] - (starship::config): No config found for "zig": Option "zig" not found
[TRACE] - (starship::modules): Took 84.312µs to compute module "zig"
[TRACE] - (starship::config): No config found for "buf": Option "buf" not found
[TRACE] - (starship::config): No config found for "buf": Option "buf" not found
[TRACE] - (starship::modules): Took 68.849µs to compute module "buf"
[TRACE] - (starship::config): No config found for "nix_shell": Option "nix_shell" not found
[TRACE] - (starship::config): No config found for "nix_shell": Option "nix_shell" not found
[TRACE] - (starship::modules): Took 74.655µs to compute module "nix_shell"
[TRACE] - (starship::config): No config found for "conda": Option "conda" not found
[TRACE] - (starship::modules): Took 2.003µs to compute module "conda"
[TRACE] - (starship::config): No config found for "cmake": Option "cmake" not found
[TRACE] - (starship::config): No config found for "cmake": Option "cmake" not found
[TRACE] - (starship::modules): Took 84.508µs to compute module "cmake"
[TRACE] - (starship::config): No config found for "cobol": Option "cobol" not found
[TRACE] - (starship::config): No config found for "cobol": Option "cobol" not found
[TRACE] - (starship::modules): Took 83.505µs to compute module "cobol"
[TRACE] - (starship::config): No config found for "daml": Option "daml" not found
[TRACE] - (starship::config): No config found for "daml": Option "daml" not found
[TRACE] - (starship::modules): Took 77.372µs to compute module "daml"
[TRACE] - (starship::config): No config found for "dart": Option "dart" not found
[TRACE] - (starship::config): No config found for "dart": Option "dart" not found
[TRACE] - (starship::modules): Took 85.307µs to compute module "dart"
[TRACE] - (starship::config): No config found for "deno": Option "deno" not found
[TRACE] - (starship::config): No config found for "deno": Option "deno" not found
[TRACE] - (starship::modules): Took 85.649µs to compute module "deno"
[TRACE] - (starship::config): No config found for "dotnet": Option "dotnet" not found
[TRACE] - (starship::config): No config found for "dotnet": Option "dotnet" not found
[TRACE] - (starship::modules): Took 92.036µs to compute module "dotnet"
[TRACE] - (starship::config): No config found for "elixir": Option "elixir" not found
[TRACE] - (starship::config): No config found for "elixir": Option "elixir" not found
[TRACE] - (starship::modules): Took 78.468µs to compute module "elixir"
[TRACE] - (starship::config): No config found for "elm": Option "elm" not found
[TRACE] - (starship::config): No config found for "elm": Option "elm" not found
[TRACE] - (starship::config): Parsing color_string: yellow
[TRACE] - (starship::config): Read predefined color: yellow
[TRACE] - (starship::modules): Took 47.472948ms to compute module "python"
[TRACE] - (starship::modules): Took 80.729µs to compute module "elm"
[TRACE] - (starship::config): No config found for "erlang": Option "erlang" not found
[TRACE] - (starship::config): No config found for "erlang": Option "erlang" not found
[TRACE] - (starship::modules): Took 117.954µs to compute module "erlang"
[TRACE] - (starship::config): No config found for "golang": Option "golang" not found
[TRACE] - (starship::config): Parsing color_string: cyan
[TRACE] - (starship::config): Read predefined color: cyan
[TRACE] - (starship::config): Parsing color_string: red
[TRACE] - (starship::config): No config found for "golang": Option "golang" not found
[TRACE] - (starship::modules): Took 248.118µs to compute module "golang"
[TRACE] - (starship::config): No config found for "haskell": Option "haskell" not found
[TRACE] - (starship::config): No config found for "haskell": Option "haskell" not found
[TRACE] - (starship::modules): Took 54.282µs to compute module "haskell"
[TRACE] - (starship::config): No config found for "helm": Option "helm" not found
[TRACE] - (starship::config): No config found for "helm": Option "helm" not found
[TRACE] - (starship::modules): Took 50.677µs to compute module "helm"
[TRACE] - (starship::config): No config found for "java": Option "java" not found
[TRACE] - (starship::config): No config found for "java": Option "java" not found
[TRACE] - (starship::modules): Took 51.991µs to compute module "java"
[TRACE] - (starship::config): No config found for "julia": Option "julia" not found
[TRACE] - (starship::config): No config found for "julia": Option "julia" not found
[TRACE] - (starship::modules): Took 48.828µs to compute module "julia"
[TRACE] - (starship::config): No config found for "kotlin": Option "kotlin" not found
[TRACE] - (starship::config): No config found for "kotlin": Option "kotlin" not found
[TRACE] - (starship::modules): Took 52.463µs to compute module "kotlin"
[TRACE] - (starship::config): No config found for "lua": Option "lua" not found
[TRACE] - (starship::config): No config found for "lua": Option "lua" not found
[TRACE] - (starship::modules): Took 83.095µs to compute module "lua"
[TRACE] - (starship::config): No config found for "nim": Option "nim" not found
[TRACE] - (starship::config): No config found for "nim": Option "nim" not found
[TRACE] - (starship::modules): Took 68.759µs to compute module "nim"
[TRACE] - (starship::config): No config found for "nodejs": Option "nodejs" not found
[TRACE] - (starship::config): No config found for "nodejs": Option "nodejs" not found
[TRACE] - (starship::modules): Took 62.78µs to compute module "nodejs"
[TRACE] - (starship::config): No config found for "ocaml": Option "ocaml" not found
[TRACE] - (starship::config): No config found for "ocaml": Option "ocaml" not found
[TRACE] - (starship::modules): Took 75.804µs to compute module "ocaml"
[TRACE] - (starship::config): No config found for "swift": Option "swift" not found
[TRACE] - (starship::config): No config found for "swift": Option "swift" not found
[TRACE] - (starship::modules): Took 59.891µs to compute module "swift"
[TRACE] - (starship::config): No config found for "terraform": Option "terraform" not found
[TRACE] - (starship::config): No config found for "terraform": Option "terraform" not found
[TRACE] - (starship::modules): Took 65.915µs to compute module "terraform"
[TRACE] - (starship::config): No config found for "vlang": Option "vlang" not found
[TRACE] - (starship::config): No config found for "vlang": Option "vlang" not found
[TRACE] - (starship::modules): Took 58.817µs to compute module "vlang"
[TRACE] - (starship::config): No config found for "git_commit": Option "git_commit" not found
[TRACE] - (starship::config): No config found for "git_commit": Option "git_commit" not found
[TRACE] - (starship::config): Read predefined color: red
[TRACE] - (starship::modules): Took 41.487351ms to compute module "directory"
[TRACE] - (starship::config): No config found for "vcsh": Option "vcsh" not found
[TRACE] - (starship::modules): Took 3.276µs to compute module "vcsh"
[TRACE] - (starship::config): No config found for "git_branch": Option "git_branch" not found
[TRACE] - (starship::config): No config found for "git_branch": Option "git_branch" not found
[TRACE] - (starship::modules): Took 57.691µs to compute module "git_branch"
[TRACE] - (starship::config): No config found for "rlang": Option "rlang" not found
[TRACE] - (starship::config): No config found for "rlang": Option "rlang" not found
[TRACE] - (starship::modules): Took 60.925µs to compute module "rlang"
[TRACE] - (starship::config): No config found for "red": Option "red" not found
[TRACE] - (starship::config): No config found for "red": Option "red" not found
[TRACE] - (starship::modules): Took 61.307µs to compute module "red"
[TRACE] - (starship::config): No config found for "ruby": Option "ruby" not found
[TRACE] - (starship::config): No config found for "ruby": Option "ruby" not found
[TRACE] - (starship::modules): Took 62.111µs to compute module "ruby"
[TRACE] - (starship::config): No config found for "scala": Option "scala" not found
[TRACE] - (starship::config): No config found for "scala": Option "scala" not found
[TRACE] - (starship::modules): Took 60.154µs to compute module "scala"
[TRACE] - (starship::config): No config found for "hg_branch": Option "hg_branch" not found
[TRACE] - (starship::modules): Took 1.042µs to compute module "hg_branch"
[TRACE] - (starship::config): No config found for "docker_context": Option "docker_context" not found
[TRACE] - (starship::config): No config found for "docker_context": Option "docker_context" not found
[TRACE] - (starship::modules): Took 66.711µs to compute module "docker_context"
[TRACE] - (starship::config): No config found for "package": Option "package" not found
[TRACE] - (starship::config): No config found for "package": Option "package" not found
[TRACE] - (starship::utils): Trying to read from "/home/matthias/vcs/github/rust/Cargo.toml"
[TRACE] - (starship::utils): File read successfully
[DEBUG] - (starship::context): Not attempting to read package.json because, it was not found during scan.
[DEBUG] - (starship::context): Not attempting to read pyproject.toml because, it was not found during scan.
[DEBUG] - (starship::context): Not attempting to read setup.cfg because, it was not found during scan.
[DEBUG] - (starship::context): Not attempting to read composer.json because, it was not found during scan.
[DEBUG] - (starship::context): Not attempting to read build.gradle because, it was not found during scan.
[DEBUG] - (starship::context): Not attempting to read Project.toml because, it was not found during scan.
[DEBUG] - (starship::context): Not attempting to read mix.exs because, it was not found during scan.
[DEBUG] - (starship::context): Not attempting to read Chart.yaml because, it was not found during scan.
[DEBUG] - (starship::context): Not attempting to read pom.xml because, it was not found during scan.
[DEBUG] - (starship::context): Not attempting to read meson.build because, it was not found during scan.
[DEBUG] - (starship::context): Not attempting to read shard.yml because, it was not found during scan.
[DEBUG] - (starship::context): Not attempting to read v.mod because, it was not found during scan.
[DEBUG] - (starship::context): Not attempting to read vpkg.json because, it was not found during scan.
[DEBUG] - (starship::context): Not attempting to read build.sbt because, it was not found during scan.
[DEBUG] - (starship::context): Not attempting to read daml.yaml because, it was not found during scan.
[DEBUG] - (starship::context): Not attempting to read pubspec.yaml because, it was not found during scan.
[TRACE] - (starship::modules): Took 1.316463ms to compute module "package"
[TRACE] - (starship::config): No config found for "package": Option "package" not found
[TRACE] - (starship::config): No config found for "bun": Option "bun" not found
[TRACE] - (starship::config): No config found for "bun": Option "bun" not found
[TRACE] - (starship::modules): Took 54.491µs to compute module "bun"
[TRACE] - (starship::config): No config found for "c": Option "c" not found
[TRACE] - (starship::config): No config found for "c": Option "c" not found
[TRACE] - (starship::modules): Took 58.897µs to compute module "c"
[TRACE] - (starship::config): No config found for "git_metrics": Option "git_metrics" not found
[TRACE] - (starship::config): No config found for "git_metrics": Option "git_metrics" not found
[TRACE] - (starship::modules): Took 62.217µs to compute module "git_metrics"
[TRACE] - (starship::config): No config found for "git_status": Option "git_status" not found
[TRACE] - (starship::config): No config found for "git_status": Option "git_status" not found
[DEBUG] - (starship::modules::git_status): New repo status created
[TRACE] - (starship::context): Executing command "git" with args ["-C", "/home/matthias/vcs/github/rust", "--no-optional-locks", "status", "--porcelain=2", "--branch"] from context
[TRACE] - (starship::config): No config found for "raku": Option "raku" not found
[TRACE] - (starship::config): No config found for "raku": Option "raku" not found
[TRACE] - (starship::modules): Took 47.094µs to compute module "raku"
[TRACE] - (starship::config): No config found for "git_state": Option "git_state" not found
[TRACE] - (starship::config): No config found for "git_state": Option "git_state" not found
[TRACE] - (starship::modules): Took 45.969µs to compute module "git_state"
[TRACE] - (starship::utils): Creating Command for binary "git"
[TRACE] - (starship::utils): Using "/usr/bin/git" as "git"
[DEBUG] - (starship::modules::rust): Rustup rustc version is RustcVersion("rustc 1.65.0-nightly (40336865f 2022-08-15)\n")
[TRACE] - (starship::config): Parsing color_string: red
[TRACE] - (starship::config): Read predefined color: red
[TRACE] - (starship::modules): Took 46.291681ms to compute module "rust"
[DEBUG] - (starship::modules::git_status): get_repo_status: git status execution failed
[TRACE] - (starship::context): Executing command "git" with args ["-C", "/home/matthias/vcs/github/rust", "--no-optional-locks", "stash", "list"] from context
[TRACE] - (starship::utils): Creating Command for binary "git"
[TRACE] - (starship::utils): Using "/usr/bin/git" as "git"
[TRACE] - (starship::utils): stdout: "", stderr: "", exit code: "Some(0)", took 3.322084ms
[TRACE] - (starship::modules): Took 512.29ms to compute module "git_status"
[TRACE] - (starship::config): No config found for "git_status": Option "git_status" not found
[TRACE] - (starship::config): Parsing color_string: green
[TRACE] - (starship::config): Read predefined color: green
[TRACE] - (starship::modules): Took 3.906437317s to compute module "git_commit"
%{%}~/vcs/github/rust%{%} %{%}(%{%}%{%}1199dbd%{%}%{%} 🏷  1.0.0-beta%{%}%{%})%{%} via %{%}🐍 %{%}%{%}%{%}%{%}v3.10.5%{%}%{%} %{%}via %{%}🦀 %{%}%{%}v1.65.0-nightly%{%}%{%} %{%}
at %{%}17:06:23%{%} %{%}❯%{%} %                                                   

so looks like getting the git commit is the problem here, hmm.

@matthiaskrgr
Copy link
Author

Using stable 1.63.0 to build starship does not make a difference.

@davidkna
Copy link
Member

That looks like there's an issue with describe. Does the problem disappear without the git tag (starship config git_commit.format '[\\($hash\\)]($style) ')?

@matthiaskrgr
Copy link
Author

Added a bunch of debug prints for getting timings, let formatter = describe_platform.try_format().ok()??; inside fn git_tag is the slow part

1660750694338 module start
1660750694388 let parsed start
1660750694388 hash start
1660750694479 hash end
1660750694479 tag start, let_git_repo
1660750694479 head_commit
1660750694479 descripe_platform
1660750694479 formatter
1660750728589 tag end
1660750728589 let parsed end, module.set_segments start
1660750728589 module end

@matthiaskrgr
Copy link
Author

Hmm, this seems to be gitoxide code?

        /// Try to find a name for the configured commit id using all prior configuration, returning `Some(describe::Format)`
        /// if one was found.
        ///
        /// Note that there will always be `Some(format)`
        pub fn try_format(&self) -> Result<Option<git_revision::describe::Format<'static>>, Error> {
            self.try_resolve()?.map(|r| r.format()).transpose()
        }

@davidkna
Copy link
Member

@matthiaskrgr It is.

@matthiaskrgr
Copy link
Author

Oooh, I noticed I had some commit checked out in the repo :)
So when HEAD is master its snappy, but when I check out the commit behind master, its slow.
I wonder if it tries to find a match between the ref/commit and a symbolic ref ("master") and this takes all that time...
cc @Byron

@matthiaskrgr
Copy link
Author

For the record:

~/vcs/github/rust (86c6ebe 🏷  1.0.0-beta) via 🐍 v3.10.5 via 🦀 v1.65.0-nightly
at 18:06:32 ❯ starship timings

 Here are the timings of modules in your prompt (>=1ms or output):
 git_commit  -  3708ms  -   "(86c6ebe 🏷  1.0.0-beta) "
 git_status  -   503ms  -   ""
 rust        -    18ms  -   "via 🦀 v1.65.0-nightly "
 python      -     7ms  -   "via 🐍 v3.10.5 "
 directory   -     4ms  -   "~/vcs/github/rust "
 hg_branch   -     1ms  -   ""
 pulumi      -     1ms  -   ""
 line_break  -    <1ms  -   "\n"
 time        -    <1ms  -   "at 18:06:43 "
 character   -    <1ms  -   "❯ "
~/vcs/github/rust (86c6ebe 🏷  1.0.0-beta) via 🐍 v3.10.5 via 🦀 v1.65.0-nightly took 4s
at 18:06:43 ❯ git checkout master
Switched to branch 'master'
~/vcs/github/rust on  master via 🐍 v3.10.5 via 🦀 v1.65.0-nightly took 604ms
at 18:06:50 ❯ starship timings

 Here are the timings of modules in your prompt (>=1ms or output):
 git_status  -  504ms  -   ""
 rust        -   14ms  -   "via 🦀 v1.65.0-nightly "
 directory   -    9ms  -   "~/vcs/github/rust "
 python      -    3ms  -   "via 🐍 v3.10.5 "
 git_branch  -   <1ms  -   "on  master "
 line_break  -   <1ms  -   "\n"
 time        -   <1ms  -   "at 18:06:52 "
 character   -   <1ms  -   "❯ "
~/vcs/github/rust on  master via 🐍 v3.10.5 via 🦀 v1.65.0-nightly took 546ms

@davidkna
Copy link
Member

@matthiaskrgr Does adding .traverse_first_parent(true) to the describe_platform in git_commit.rs help? I assume it's traversing too many commits or something in that manner, though I'm not sure if that will be enough. The gitoxide gix can print the number of commits traversed via gix commit describe --statistics.

@matthiaskrgr
Copy link
Author

gix commit describe --statistics

traversed 180771 commits
homu-tmp-141910-g86c6ebee8fa

let formatter = describe_platform.traverse_first_parent(true).try_format().ok()??;
brings it down from
git_commit - 3788ms - "(86c6ebe 🏷 1.0.0-beta) "
to
git_commit - 349ms - "(86c6ebe 🏷 1.0.0-beta) "
😄

@Byron
Copy link
Contributor

Byron commented Aug 18, 2022

Thanks for debugging this! While I quietly watching how this unfolds I had a strong hunch that it's the describe functionality - it has a lot of potential for being slow in pathological cases, and simply doing a git checkout @~1 allows me to reproduce it. Here is the results, also in comparison to git.

rust (14a459b 🏷  1.0.0-beta) via 🐍
❯ time git describe HEAD --debug
describe HEAD
No exact match on refs or tags, searching to describe
finished search at 7140d7c52bdf55daf0b978a19706d20c3bf7ee92
 annotated     156705 1.0.0-beta
 annotated     158575 1.0.0-alpha.2
 annotated     160641 1.0.0-alpha
 annotated     164398 0.12.0
 annotated     169772 0.10
 annotated     172074 0.9
 annotated     174726 0.8
 annotated     177831 0.7
 annotated     180685 0.6
 annotated     181375 0.11.0
traversed 181377 commits
1.0.0-beta-156705-g14a459bf37b
git describe HEAD --debug  1.10s user 0.02s system 99% cpu 1.118 total

rust (14a459b 🏷  1.0.0-beta) via 🐍
❯ time gix commit describe  --statistics
traversed 181377 commits
1.0.0-beta-156705-g14a459bf37b
gix commit describe --statistics  1.85s user 0.01s system 100% cpu 1.858 total

I paid a lot of attention to implement the algorithm to match git exactly, which also includes the worst-case cost for the search. I did notice that git is much faster in making lookups in the commit-graph and it seems the slowing factor here is the hashmap accesses that make up the graph, despite me trying my best to optimize it.

Maybe there is still some performance to be eeked out, and I certainly hope so, as gitoxide is already faster in object database access even on a single core, and it should be possible to get the commitgraph fast as well. Will take a another look.

@davidkna Assuming the worst which is me not being able to get it significantly faster, what would be alternatives to mitigate this? I can imagine exposing a configuration setting to traverse the first parent only, or to shell it out to git instead. The latter, however, doesn't do miracles either and to me 1.18s is too slow as well to be suitable. And knowing how this works, getting this case into the below 100ms range will only be possible when using the git commit-graph:

rust (14a459b 🏷  1.0.0-beta) via 🐍
❯ git commit-graph write
Finding commits for commit graph among packed objects: 100% (1964700/1964700), done.
Expanding reachable commits in commit graph: 201038, done.

rust (14a459b 🏷  1.0.0-beta) via 🐍 took 3s
❯ time git describe HEAD --debug
describe HEAD
No exact match on refs or tags, searching to describe
finished search at 7140d7c52bdf55daf0b978a19706d20c3bf7ee92
 annotated     156705 1.0.0-beta
 annotated     158575 1.0.0-alpha.2
 annotated     160641 1.0.0-alpha
 annotated     164398 0.12.0
 annotated     169772 0.10
 annotated     172074 0.9
 annotated     174726 0.8
 annotated     177831 0.7
 annotated     180685 0.6
 annotated     181375 0.11.0
traversed 181377 commits
1.0.0-beta-156705-g14a459bf37b
git describe HEAD --debug  0.06s user 0.02s system 97% cpu 0.084 total

However, that is not usually available in typical people's repositories. gitoxide could learn to use it (it has the git-commitgraph crate for reading already), but it's nothing I'd want to do right now given there seem to be better alternative to speed up the common case, namely:

  • starship settings to use first parent only or to use a smaller set of input tags (even though I didn't check if this makes a meaningful difference) - this means 190ms time for gitoxide without commit-graph and 140ms for git.
  • shell it out to git for up to 37% shorter times

Passing first_parent() by default in starship would be my preference, maybe along with an option to use 'precise' describes at potentially high cost.

That was a lot, what's your thoughts :)?

Byron added a commit to Byron/starship that referenced this issue Aug 18, 2022
Related to starship#4275 bringing
performance to spitting distance compared to git.
Byron added a commit to Byron/gitoxide that referenced this issue Aug 18, 2022
Byron added a commit to Byron/starship that referenced this issue Aug 18, 2022
Related to starship#4275 bringing
performance to spitting distance compared to git.
@Byron
Copy link
Contributor

Byron commented Aug 18, 2022

So, I took another look, this time with a profiler, and noticed that 80% of the time is actually spent on the object database, which was unexpected.

It turned out that the graph traversal of 'commit describe' benefits greatly from having an object cache, so that multiple accesses of the same commit can be cached. In the pending gitoxide upgrade I am setting a small object cache that is big enough to bring gitoxide into spitting distance to git. The same fix was applied to gix, but in the meantime you can check it like this:

❯ starship timings # with #4277 applied, down from ~1850ms

 Here are the timings of modules in your prompt (>=1ms or output):
 git_commit   -  1172ms  -   "(14a459b 🏷  1.0.0-beta) "
 git_status   -   507ms  -   ""
 git_metrics  -   203ms  -   ""
 directory    -    <1ms  -   "rust "
 python       -    <1ms  -   "via 🐍 "
 line_break   -    <1ms  -   "\n"
 character    -    <1ms  -   ""

rust (14a459b 🏷  1.0.0-beta) via 🐍
❯ time git describe HEAD
1.0.0-beta-156705-g14a459bf37b
git describe HEAD  1.10s user 0.01s system 99% cpu 1.114 total

rust (14a459b 🏷  1.0.0-beta) via 🐍
❯ time GITOXIDE_OBJECT_CACHE_MEMORY=4MB gix commit describe
1.0.0-beta-156705-g14a459bf37b
GITOXIDE_OBJECT_CACHE_MEMORY=1MB gix commit describe  1.16s user 0.02s system 99% cpu 1.191 total

The cache size here is the smallest one that gave fast times time 2 in case this is good for bigger repositories, but starship was also modified to read GITOXIDE_OBJECT_CACHE_MEMORY to allow experimentation.

I think with this change shelling out the operation isn't beneficial anymore. Further speedups are certainly possible, it looks like 20% of the time is still spent in parsing commits, and that could probably be faster if nom wasn't used, and maybe that would be enough to match git performance or be a little faster.

In any case, however, I feel that starship wants first-parent behaviour by default to bring the time down to ~150ms, potentially with an option to not do that as it may alter the describe output.

andytom pushed a commit that referenced this issue Aug 18, 2022
* upgrade `gitoxide` to v0.21

This release comes with lenient configuration handling by default,
allowing to open repositories even their configuration values are
invalid (even for git), as long as there are viable defaults.

Furthermore this release adds the ability to open submodule repsitories.

Fixes #4266 and
fixes #4272

* Assure an object cache is set to speed up `commit.describe()`

Related to #4275 bringing
performance to spitting distance compared to git.
Indyandie pushed a commit to Indyandie/starship that referenced this issue Jul 26, 2023
* upgrade `gitoxide` to v0.21

This release comes with lenient configuration handling by default,
allowing to open repositories even their configuration values are
invalid (even for git), as long as there are viable defaults.

Furthermore this release adds the ability to open submodule repsitories.

Fixes starship#4266 and
fixes starship#4272

* Assure an object cache is set to speed up `commit.describe()`

Related to starship#4275 bringing
performance to spitting distance compared to git.
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
🐛 bug Something isn't working as expected.
Projects
None yet
Development

Successfully merging a pull request may close this issue.

4 participants