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.

Sign up for GitHub

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

Jump to bottom

Very slow git credential manager #424

Closed
2 tasks
LukeMauldin opened this issue Aug 25, 2021 · 6 comments · Fixed by #547
Closed
2 tasks

Very slow git credential manager #424

LukeMauldin opened this issue Aug 25, 2021 · 6 comments · Fixed by #547
Assignees
@vtbassmatt
Labels
host:generic Specific to the generic (basic/WIA) host provider performance An issue with performance

Comments

@LukeMauldin
Copy link

Which version of GCM Core are you using?
2.0.498+7ad55fb809

Which Git host provider are you trying to connect to?
Local gitea instance

Can you access the remote repository directly in the browser using the remote URL?

  • [ X ] Yes
  • No, I get a permission error
  • No, for a different reason - please describe

Expected behavior

When I do a Git clone of a repository, I expect the clone operation to happen quickly but each invocation of the git credential manager takes at least 5 seconds. See the logs below. The operations complete without prompting me for my password but they are just very slow.

Actual behavior

The operation occurs successfully.

Logs

Performance Logs

07:54:35.483985 run-command.c:666       trace: run_command: 'git credential-manager-core get'
07:54:36.638552 exec-cmd.c:237          trace: resolved executable dir: C:/Users/XXX/AppData/Local/Programs/Git/mingw32/libexec/git-core
07:54:36.640555 git.c:744               trace: exec: git-credential-manager-core get
07:54:36.640555 run-command.c:666       trace: run_command: git-credential-manager-core get
07:54:42.250496 trace.c:487             performance: 5.611020900 s: git command: 'C:\Users\XXX\AppData\Local\Programs\Git\mingw32\libexec\git-core\git.exe' credential-manager-core get
....
07:54:42.305499 run-command.c:666       trace: run_command: 'git credential-manager-core store'
07:54:43.158074 exec-cmd.c:237          trace: resolved executable dir: C:/Users/XXX/AppData/Local/Programs/Git/mingw32/libexec/git-core
07:54:43.160074 git.c:744               trace: exec: git-credential-manager-core store
07:54:43.160074 run-command.c:666       trace: run_command: git-credential-manager-core store
07:54:48.699227 trace.c:487             performance: 5.540569200 s: git command: 'C:\Users\XXX\AppData\Local\Programs\Git\mingw32\libexec\git-core\git.exe' credential-manager-core store

Git/GCM Trace Logs

07:59:18.670234 exec-cmd.c:237          trace: resolved executable dir: C:/Users/XXX/AppData/Local/Programs/Git/mingw32/bin
07:59:18.671234 git.c:455               trace: built-in: git clone https://XXXXX
Cloning into 'liaisonlogminerworker'...
07:59:18.734236 run-command.c:666       trace: run_command: git remote-https origin https://XXXXX
07:59:19.119236 exec-cmd.c:237          trace: resolved executable dir: C:/Users/XXX/AppData/Local/Programs/Git/mingw32/libexec/git-core
07:59:19.121239 git.c:744               trace: exec: git-remote-https origin https://XXXXX
07:59:19.121239 run-command.c:666       trace: run_command: git-remote-https origin https://XXXXX
07:59:19.504802 exec-cmd.c:237          trace: resolved executable dir: C:/Users/XXX/AppData/Local/Programs/Git/mingw32/libexec/git-core
07:59:19.550802 run-command.c:666       trace: run_command: 'git credential-manager-core get'
07:59:20.396364 exec-cmd.c:237          trace: resolved executable dir: C:/Users/XXX/AppData/Local/Programs/Git/mingw32/libexec/git-core
07:59:20.398365 git.c:744               trace: exec: git-credential-manager-core get
07:59:20.398365 run-command.c:666       trace: run_command: git-credential-manager-core get
07:59:22.021992 ...\Application.cs:80   trace: [RunInternalAsync] Version: 2.0.498.54650
07:59:22.029990 ...\Application.cs:81   trace: [RunInternalAsync] Runtime: .NET Framework 4.0.30319.42000
07:59:22.029990 ...\Application.cs:82   trace: [RunInternalAsync] Platform: Windows (x86-64)
07:59:22.029990 ...\Application.cs:83   trace: [RunInternalAsync] AppPath: C:\Users\XXX\AppData\Local\Programs\Git\mingw32\libexec\git-core\git-credential-manager-core.exe
07:59:22.029990 ...\Application.cs:84   trace: [RunInternalAsync] Arguments: get
07:59:22.094989 ...GitCommandBase.cs:35 trace: [ExecuteAsync] Start 'get' command...
07:59:22.106991 ...GitCommandBase.cs:49 trace: [ExecuteAsync] Detecting host provider for input:
07:59:22.107991 ...GitCommandBase.cs:50 trace: [ExecuteAsync]   protocol=https
07:59:22.107991 ...GitCommandBase.cs:50 trace: [ExecuteAsync]   host=XXXXX
07:59:23.460124 ...viderRegistry.cs:149 trace: [GetProviderAsync] Performing auto-detection of host provider.
07:59:23.462125 ...viderRegistry.cs:162 trace: [GetProviderAsync] Checking against 3 host providers registered with priority 'Normal'.
07:59:23.464123 ...viderRegistry.cs:154 trace: [GetProviderAsync] Querying remote URL for host provider auto-detection.
07:59:23.465122 ...pClientFactory.cs:54 trace: [CreateClient] Creating new HTTP client instance...
07:59:26.333243 ...etHostProvider.cs:72 trace: [IsSupported] Host isn't supported as Bitbucket
07:59:26.333243 ...viderRegistry.cs:162 trace: [GetProviderAsync] Checking against 1 host providers registered with priority 'Low'.
07:59:26.334243 ...GitCommandBase.cs:52 trace: [ExecuteAsync] Host provider 'Generic' was selected.
07:59:26.337244 ...\HostProvider.cs:128 trace: [GetCredentialAsync] Looking for existing credential in store with service=https://XXXXX account=...
07:59:26.342242 ...\HostProvider.cs:142 trace: [GetCredentialAsync] Existing credential found.
07:59:26.342242 ...GitCommandBase.cs:56 trace: [ExecuteAsync] End 'get' command...
07:59:26.412888 run-command.c:666       trace: run_command: 'git credential-manager-core store'
07:59:27.306884 exec-cmd.c:237          trace: resolved executable dir: C:/Users/XXX/AppData/Local/Programs/Git/mingw32/libexec/git-core
07:59:27.308888 git.c:744               trace: exec: git-credential-manager-core store
07:59:27.308888 run-command.c:666       trace: run_command: git-credential-manager-core store
07:59:28.368082 ...\Application.cs:80   trace: [RunInternalAsync] Version: 2.0.498.54650
07:59:28.445078 ...\Application.cs:81   trace: [RunInternalAsync] Runtime: .NET Framework 4.0.30319.42000
07:59:28.445078 ...\Application.cs:82   trace: [RunInternalAsync] Platform: Windows (x86-64)
07:59:28.445078 ...\Application.cs:83   trace: [RunInternalAsync] AppPath: C:\Users\XXX\AppData\Local\Programs\Git\mingw32\libexec\git-core\git-credential-manager-core.exe
07:59:28.445078 ...\Application.cs:84   trace: [RunInternalAsync] Arguments: store
07:59:28.512079 ...GitCommandBase.cs:35 trace: [ExecuteAsync] Start 'store' command...
07:59:28.529079 ...GitCommandBase.cs:49 trace: [ExecuteAsync] Detecting host provider for input:
07:59:28.531081 ...GitCommandBase.cs:50 trace: [ExecuteAsync]   protocol=https
07:59:28.531081 ...GitCommandBase.cs:50 trace: [ExecuteAsync]   host=XXXXX
07:59:28.531081 ...GitCommandBase.cs:50 trace: [ExecuteAsync]   username=XXX
07:59:28.531081 ...GitCommandBase.cs:50 trace: [ExecuteAsync]   password=********
07:59:29.899731 ...viderRegistry.cs:149 trace: [GetProviderAsync] Performing auto-detection of host provider.
07:59:29.901731 ...viderRegistry.cs:162 trace: [GetProviderAsync] Checking against 3 host providers registered with priority 'Normal'.
07:59:29.903732 ...viderRegistry.cs:154 trace: [GetProviderAsync] Querying remote URL for host provider auto-detection.
07:59:29.904734 ...pClientFactory.cs:54 trace: [CreateClient] Creating new HTTP client instance...
07:59:33.036482 ...etHostProvider.cs:72 trace: [IsSupported] Host isn't supported as Bitbucket
07:59:33.036482 ...viderRegistry.cs:162 trace: [GetProviderAsync] Checking against 1 host providers registered with priority 'Low'.
07:59:33.037482 ...GitCommandBase.cs:52 trace: [ExecuteAsync] Host provider 'Generic' was selected.
07:59:33.037482 ...\HostProvider.cs:162 trace: [StoreCredentialAsync] Storing credential with service=https://XXXXX account=XXX...
07:59:33.050479 ...\HostProvider.cs:164 trace: [StoreCredentialAsync] Credential was successfully stored.
07:59:33.050479 ...GitCommandBase.cs:56 trace: [ExecuteAsync] End 'store' command...
07:59:33.088481 run-command.c:666       trace: run_command: 'C:/Users/XXX/AppData/Local/Programs/Git\ Credential\ Manager\ Core/git-credential-manager-core.exe store'
07:59:34.693676 ...\Application.cs:80   trace: [RunInternalAsync] Version: 2.0.498.54650
07:59:34.701675 ...\Application.cs:81   trace: [RunInternalAsync] Runtime: .NET Framework 4.0.30319.42000
07:59:34.701675 ...\Application.cs:82   trace: [RunInternalAsync] Platform: Windows (x86-64)
07:59:34.701675 ...\Application.cs:83   trace: [RunInternalAsync] AppPath: C:\Users\XXX\AppData\Local\Programs\Git Credential Manager Core\git-credential-manager-core.exe
07:59:34.702675 ...\Application.cs:84   trace: [RunInternalAsync] Arguments: store
07:59:34.768675 ...GitCommandBase.cs:35 trace: [ExecuteAsync] Start 'store' command...
07:59:34.781677 ...GitCommandBase.cs:49 trace: [ExecuteAsync] Detecting host provider for input:
07:59:34.784673 ...GitCommandBase.cs:50 trace: [ExecuteAsync]   protocol=https
07:59:34.784673 ...GitCommandBase.cs:50 trace: [ExecuteAsync]   host=XXXXX
07:59:34.784673 ...GitCommandBase.cs:50 trace: [ExecuteAsync]   username=XXX
07:59:34.784673 ...GitCommandBase.cs:50 trace: [ExecuteAsync]   password=********
07:59:36.152240 ...viderRegistry.cs:149 trace: [GetProviderAsync] Performing auto-detection of host provider.
07:59:36.154241 ...viderRegistry.cs:162 trace: [GetProviderAsync] Checking against 3 host providers registered with priority 'Normal'.
07:59:36.156242 ...viderRegistry.cs:154 trace: [GetProviderAsync] Querying remote URL for host provider auto-detection.
07:59:36.157240 ...pClientFactory.cs:54 trace: [CreateClient] Creating new HTTP client instance...
07:59:39.006984 ...etHostProvider.cs:72 trace: [IsSupported] Host isn't supported as Bitbucket
07:59:39.007982 ...viderRegistry.cs:162 trace: [GetProviderAsync] Checking against 1 host providers registered with priority 'Low'.
07:59:39.007982 ...GitCommandBase.cs:52 trace: [ExecuteAsync] Host provider 'Generic' was selected.
07:59:39.008983 ...\HostProvider.cs:162 trace: [StoreCredentialAsync] Storing credential with service=https://XXXXX account=XXX...
07:59:39.020983 ...\HostProvider.cs:164 trace: [StoreCredentialAsync] Credential was successfully stored.
07:59:39.020983 ...GitCommandBase.cs:56 trace: [ExecuteAsync] End 'store' command...
remote: Enumerating objects: 269, done.
remote: Total 269 (delta 0), reused 0 (delta 0), pack-reused 269
07:59:39.166985 run-command.c:666       trace: run_command: git index-pack --stdin -v --fix-thin '--keep=fetch-pack 19600 on USGVTMV-CTX004' --check-self-contained-and-connected
07:59:39.520549 exec-cmd.c:237          trace: resolved executable dir: C:/Users/XXX/AppData/Local/Programs/Git/mingw32/libexec/git-core
07:59:39.523548 git.c:455               trace: built-in: git index-pack --stdin -v --fix-thin '--keep=fetch-pack 19600 on USGVTMV-CTX004' --check-self-contained-and-connected
Receiving objects: 100% (269/269), 43.06 KiB | 2.53 MiB/s, done.
Resolving deltas: 100% (153/153), done.
07:59:39.577550 run-command.c:666       trace: run_command: git rev-list --objects --stdin --not --all --quiet --alternate-refs '--progress=Checking connectivity'
07:59:39.906549 exec-cmd.c:237          trace: resolved executable dir: C:/Users/XXX/AppData/Local/Programs/Git/mingw32/libexec/git-core
07:59:39.908547 git.c:455               trace: built-in: git rev-list --objects --stdin --not --all --quiet --alternate-refs '--progress=Checking connectivity'
@LukeMauldin LukeMauldin added the auth-issue An issue authenticating to a host label Aug 25, 2021
@mjcheetham
Copy link
Collaborator

From the logs I can see there is about a 1.6 second startup time, which is largely unavoidable. There may be some perf wins we can make from some optimisations or better use of AOT compilation (with a move to .NET 5/6 on Windows).

...
07:59:20.398365 run-command.c:666       trace: run_command: git-credential-manager-core get
07:59:22.021992 ...\Application.cs:80   trace: [RunInternalAsync] Version: 2.0.498.54650
...

However the largest bulk of time spent in GCM is doing the remote probing network call, for auto-detection of host providers; at least 2.8 seconds.

...
07:59:22.094989 ...GitCommandBase.cs:35 trace: [ExecuteAsync] Start 'get' command...
07:59:22.106991 ...GitCommandBase.cs:49 trace: [ExecuteAsync] Detecting host provider for input:
07:59:22.107991 ...GitCommandBase.cs:50 trace: [ExecuteAsync]   protocol=https
07:59:22.107991 ...GitCommandBase.cs:50 trace: [ExecuteAsync]   host=XXXXX
07:59:23.460124 ...viderRegistry.cs:149 trace: [GetProviderAsync] Performing auto-detection of host provider.
07:59:23.462125 ...viderRegistry.cs:162 trace: [GetProviderAsync] Checking against 3 host providers registered with priority 'Normal'.
07:59:23.464123 ...viderRegistry.cs:154 trace: [GetProviderAsync] Querying remote URL for host provider auto-detection.
07:59:23.465122 ...pClientFactory.cs:54 trace: [CreateClient] Creating new HTTP client instance...
07:59:26.333243 ...etHostProvider.cs:72 trace: [IsSupported] Host isn't supported as Bitbucket
07:59:26.333243 ...viderRegistry.cs:162 trace: [GetProviderAsync] Checking against 1 host providers registered with priority 'Low'.
07:59:26.334243 ...GitCommandBase.cs:52 trace: [ExecuteAsync] Host provider 'Generic' was selected.
...

Since it looks like you're using a "generic" provider here for the XXXXX host (i.e, it's not GitHub, Bitbucket, or Azure Repos), you can workaround/avoid this slow auto-detection.

Run the following to set Git configuration, telling GCM to use the "generic" provider (it won't make this probe call) for the host:

git config --global credential.https://XXXXX.provider generic

..where XXXXX is your redacted hostname, like example.com.

@mjcheetham mjcheetham added host:generic Specific to the generic (basic/WIA) host provider performance An issue with performance and removed auth-issue An issue authenticating to a host labels Aug 26, 2021
@LukeMauldin
Copy link
Author

The suggestion to set the provider to generic reduced the total clone time from 20 seconds down to around 5 seconds which is a huge improvement. It is still much slower on this specific machine so I am going to work with my IT team to figure out if a security agent is making normal operations slower.
I didn't see this option documented in any of the READMEs or troubleshooting guides. Maybe it can be added?

@vtbassmatt
Copy link
Contributor

@vtbassmatt to document

@vtbassmatt vtbassmatt self-assigned this Sep 28, 2021
@HecticSerenity
Copy link

Is there a reason the GCM is called twice to 'store'? See logs in OP.

@mjcheetham
Copy link
Collaborator

@vtbassmatt not sure if this is still worth documenting as the latest GCM release will automatically set this setting for you after 1 successful auto-discovery probe?

@vtbassmatt
Copy link
Contributor

Whoops, sorry for the lack of followup here. I'll still try to mention it someplace, but good to know it'll be encountered less frequently now!

vtbassmatt added a commit that referenced this issue Nov 19, 2021
@vtbassmatt
FAQ about probing
30a85cd 
fixes #424
@vtbassmatt vtbassmatt mentioned this issue Nov 19, 2021
Merged
@ldennington ldennington mentioned this issue Dec 10, 2021
Merged
ldennington pushed a commit to ldennington/git-credential-manager that referenced this issue Mar 1, 2022
@vtbassmatt @ldennington
FAQ about probing
779eae4 
fixes git-ecosystem#424
ldennington pushed a commit to ldennington/git-credential-manager that referenced this issue Mar 8, 2022
@vtbassmatt @ldennington
FAQ about probing
b641ba1 
fixes git-ecosystem#424
ldennington pushed a commit to ldennington/git-credential-manager that referenced this issue Jun 15, 2022
@vtbassmatt @ldennington
FAQ about probing
b9d96f0 
fixes git-ecosystem#424
imgbot bot pushed a commit to Jeverett3000/Git-Credential-Manager-Core that referenced this issue Nov 2, 2022
@vtbassmatt @ImgBotApp
FAQ about probing
7d95e83 
fixes git-ecosystem#424
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@vtbassmatt vtbassmatt

Labels
host:generic Specific to the generic (basic/WIA) host provider performance An issue with performance
Projects
None yet
Milestone
No milestone
Development

Successfully merging a pull request may close this issue.

Batch of documentation fixes git-ecosystem/git-credential-manager
4 participants
@vtbassmatt @LukeMauldin @mjcheetham @HecticSerenity