Git credential manager - seems slow to do git push even if there are no changes #1169

DerekSMorin · 2023-03-27T22:04:05Z

DerekSMorin
Mar 27, 2023

If I run "git push" in conemu it seems to take 7 or 8 seconds even if there are no changes.

From 14:50:04 to 14:50:06 it seems to be validating credentials.
I put a few blank lines to indicate the end of that.
After that it seems to take a while storing the credentials.

I'm not sure if I have a configuration problem or if this behaviour is expected. It seemed slow to me, so I started looking into it.

Also, I hope this is the right place for this question :)

14:50:04.004275 ...\Application.cs:95 trace: [RunInternalAsync] Version: 2.0.935.18315
14:50:04.008805 ...\Application.cs:96 trace: [RunInternalAsync] Runtime: .NET Framework 4.0.30319.42000
14:50:04.008805 ...\Application.cs:97 trace: [RunInternalAsync] Platform: Windows (x86-64)
14:50:04.009812 ...\Application.cs:98 trace: [RunInternalAsync] OSVersion: 10.0 (build 19044)
14:50:04.009812 ...\Application.cs:99 trace: [RunInternalAsync] AppPath: C:\Program Files\Git\mingw64\bin\git-credential-manager
14:50:04.009812 ...\Application.cs:100 trace: [RunInternalAsync] InstallDir: C:\Program Files\Git\mingw64\bin
14:50:04.010813 ...\Application.cs:101 trace: [RunInternalAsync] Arguments: get
14:50:04.058812 ...GitCommandBase.cs:33 trace: [ExecuteAsync] Start 'get' command...
14:50:04.066813 ...GitCommandBase.cs:47 trace: [ExecuteAsync] Detecting host provider for input:
14:50:04.068844 ...GitCommandBase.cs:48 trace: [ExecuteAsync] protocol=https
14:50:04.068844 ...GitCommandBase.cs:48 trace: [ExecuteAsync] host=bitbucket.org
14:50:04.068844 ...GitCommandBase.cs:48 trace: [ExecuteAsync] username=DerekMorin
14:50:04.166811 ...oviderRegistry.cs:99 trace: [GetProviderAsync] Host provider override was set id='bitbucket'
14:50:04.169808 ...GitCommandBase.cs:50 trace: [ExecuteAsync] Host provider 'Bitbucket' was selected.
14:50:04.369809 ...tHostProvider.cs:272 trace: [GetSupportedAuthenticationModesAsync] https://bitbucket.org/ is bitbucket.org - authentication schemes: 'All'
14:50:04.546556 ...tHostProvider.cs:103 trace: [GetStoredCredentials] Look for existing credentials under https://bitbucket.org ...
14:50:04.917891 ...tHostProvider.cs:113 trace: [GetStoredCredentials] Found stored credentials: DerekMorin/********
14:50:05.100889 ...tHostProvider.cs:393 trace: [ValidateCredentialsWork] Validate credentials (DerekMorin/) are fresh for https://bitbucket.org/ ...
14:50:05.112891 ...tbucketRestApi.cs:36 trace: [GetUserInformationAsync] HTTP: GET https://api.bitbucket.org/2.0/user
14:50:05.112891 ...pClientFactory.cs:58 trace: [CreateClient] Creating new HTTP client instance...
14:50:06.285627 ...pClientFactory.cs:97 trace: [CreateClient] Custom certificate verification has been enabled with certificate bundle at C:/Program Files/Git/mingw64/etc/ssl/certs/ca-bundle.crt
14:50:06.945235 ...tbucketRestApi.cs:39 trace: [GetUserInformationAsync] HTTP: Response 200 [OK]
14:50:06.960978 ...tHostProvider.cs:402 trace: [ValidateCredentialsWork] Validated existing credentials using OAuth
14:50:06.960978 ...\GetCommand.cs:39 trace: [ExecuteInternalAsync] Writing credentials to output:
14:50:06.962259 ...\GetCommand.cs:40 trace: [ExecuteInternalAsync] protocol=https
14:50:06.962259 ...\GetCommand.cs:40 trace: [ExecuteInternalAsync] host=bitbucket.org
14:50:06.962259 ...\GetCommand.cs:40 trace: [ExecuteInternalAsync] username=DerekMorin
14:50:06.963268 ...\GetCommand.cs:40 trace: [ExecuteInternalAsync] password=
14:50:06.963268 ...GitCommandBase.cs:54 trace: [ExecuteAsync] End 'get' command...

14:50:09.326352 ...\Application.cs:95 trace: [RunInternalAsync] Version: 2.0.935.18315
14:50:09.331350 ...\Application.cs:96 trace: [RunInternalAsync] Runtime: .NET Framework 4.0.30319.42000
14:50:09.331350 ...\Application.cs:97 trace: [RunInternalAsync] Platform: Windows (x86-64)
14:50:09.331350 ...\Application.cs:98 trace: [RunInternalAsync] OSVersion: 10.0 (build 19044)
14:50:09.332350 ...\Application.cs:99 trace: [RunInternalAsync] AppPath: C:\Program Files\Git\mingw64\bin\git-credential-manager
14:50:09.333028 ...\Application.cs:100 trace: [RunInternalAsync] InstallDir: C:\Program Files\Git\mingw64\bin
14:50:09.334035 ...\Application.cs:101 trace: [RunInternalAsync] Arguments: store
14:50:09.384072 ...GitCommandBase.cs:33 trace: [ExecuteAsync] Start 'store' command...
14:50:09.392367 ...GitCommandBase.cs:47 trace: [ExecuteAsync] Detecting host provider for input:
14:50:09.393361 ...GitCommandBase.cs:48 trace: [ExecuteAsync] protocol=https
14:50:09.393361 ...GitCommandBase.cs:48 trace: [ExecuteAsync] host=bitbucket.org
14:50:09.393361 ...GitCommandBase.cs:48 trace: [ExecuteAsync] username=DerekMorin
14:50:09.394367 ...GitCommandBase.cs:48 trace: [ExecuteAsync] password=********
14:50:09.497373 ...oviderRegistry.cs:99 trace: [GetProviderAsync] Host provider override was set id='bitbucket'
14:50:09.500375 ...GitCommandBase.cs:50 trace: [ExecuteAsync] Host provider 'Bitbucket' was selected.
14:50:09.501364 ...tHostProvider.cs:319 trace: [StoreCredentialAsync] Storing credential...
14:50:09.854353 ...tHostProvider.cs:321 trace: [StoreCredentialAsync] Credential was successfully stored.
14:50:09.854353 ...GitCommandBase.cs:54 trace: [ExecuteAsync] End 'store' command...
14:50:11.109997 ...\Application.cs:95 trace: [RunInternalAsync] Version: 2.0.935.18315
14:50:11.115960 ...\Application.cs:96 trace: [RunInternalAsync] Runtime: .NET Framework 4.0.30319.42000
14:50:11.115960 ...\Application.cs:97 trace: [RunInternalAsync] Platform: Windows (x86-64)
14:50:11.115960 ...\Application.cs:98 trace: [RunInternalAsync] OSVersion: 10.0 (build 19044)
14:50:11.115960 ...\Application.cs:99 trace: [RunInternalAsync] AppPath: C:\Program Files\Git\mingw64\bin\git-credential-manager
14:50:11.116959 ...\Application.cs:100 trace: [RunInternalAsync] InstallDir: C:\Program Files\Git\mingw64\bin
14:50:11.116959 ...\Application.cs:101 trace: [RunInternalAsync] Arguments: store
14:50:11.164991 ...GitCommandBase.cs:33 trace: [ExecuteAsync] Start 'store' command...
14:50:11.173991 ...GitCommandBase.cs:47 trace: [ExecuteAsync] Detecting host provider for input:
14:50:11.174963 ...GitCommandBase.cs:48 trace: [ExecuteAsync] protocol=https
14:50:11.174963 ...GitCommandBase.cs:48 trace: [ExecuteAsync] host=bitbucket.org
14:50:11.175958 ...GitCommandBase.cs:48 trace: [ExecuteAsync] username=DerekMorin
14:50:11.175958 ...GitCommandBase.cs:48 trace: [ExecuteAsync] password=********
14:50:11.271991 ...oviderRegistry.cs:99 trace: [GetProviderAsync] Host provider override was set id='bitbucket'
14:50:11.274993 ...GitCommandBase.cs:50 trace: [ExecuteAsync] Host provider 'Bitbucket' was selected.
14:50:11.275994 ...tHostProvider.cs:319 trace: [StoreCredentialAsync] Storing credential...
14:50:11.615597 ...tHostProvider.cs:321 trace: [StoreCredentialAsync] Credential was successfully stored.
14:50:11.616667 ...GitCommandBase.cs:54 trace: [ExecuteAsync] End 'store' command...
Everything up-to-date

Answered by ldennington

Apr 10, 2023

As a heads up, we do have future plans to make use of the password_expiry_utc attribute to improve this workflow. Tracking at #268.

View full answer

hickford · 2023-03-30T01:36:39Z

hickford
Mar 30, 2023
Collaborator

The logs show that GCM is invoked three times -- one "get" and two "store" commands. The time between is spent in Git. You can export GIT_TRACE=1 to show this more clearly. https://git-scm.com/docs/git#Documentation/git.txt-codeGITTRACEcode

That first "get" seems slow, taking 3.0 seconds to retrieve stored credentials. The slowest part appears to be "Creating new HTTP client instance ... Custom certificate verification has been enabled" taking 1.2 seconds . GCM then makes a HTTP request in order to "Validated existing credentials using OAuth" taking 0.7 seconds. (If validation failed, GCM would do OAuth token refresh.)

Are you conciously using custom certificate verification? I'm not familiar with this feature. As a workaround, perhaps you could turn it off, at least for certain hosts?

An elegant fix in GCM would be to store the OAuth token expiry in Git's password_expiry_utc attribute (introduced Git 2.40) . With this information, a HTTP request to validate the OAuth credentials would no longer be necessary. This would save 1.9 seconds total.

1 reply

DerekSMorin Mar 30, 2023
Author

Thanks! I've attached the output of GIT_TRACE. To me it looks like the bulk of the time is in credential manager activities but I could be reading things incorrectly. I can't remember what I ran to get the original logging that I did.

I'm not consciously using custom certificate verification, but I can't remember what I did to get bitbucket authorization working. I think it was related to using app passwords instead of an Atlassian account password.

https://bitbucket.org/blog/deprecating-atlassian-account-password-for-bitbucket-api-and-git-activity

C:\scriptcode>set GIT_TRACE=1

C:\scriptcode>git push
06:40:44.134245 exec-cmd.c:237 trace: resolved executable dir: C:/Program Files/Git/mingw64/bin
06:40:44.154279 git.c:439 trace: built-in: git push
06:40:44.156245 run-command.c:655 trace: run_command: GIT_DIR=.git git remote-https origin https://...
06:40:44.198244 exec-cmd.c:237 trace: resolved executable dir: C:/Program Files/Git/mingw64/libexec/git-core
06:40:44.201245 git.c:725 trace: exec: git-remote-https origin https://...
06:40:44.201245 run-command.c:655 trace: run_command: git-remote-https origin https:...
06:40:44.244244 exec-cmd.c:237 trace: resolved executable dir: C:/Program Files/Git/mingw64/libexec/git-core
06:40:44.691937 run-command.c:655 trace: run_command: 'C:/Program\ Files/Git/mingw64/bin/git-credential-manager get'
06:40:48.431923 run-command.c:655 trace: run_command: 'C:/Program\ Files/Git/mingw64/bin/git-credential-manager store'
06:40:50.091009 run-command.c:655 trace: run_command: 'git credential-manager store'
06:40:50.225004 exec-cmd.c:237 trace: resolved executable dir: C:/Program Files/Git/mingw64/libexec/git-core
06:40:50.228004 git.c:725 trace: exec: git-credential-manager store
06:40:50.228004 run-command.c:655 trace: run_command: git-credential-manager store
Everything up-to-date

ldennington · 2023-04-10T21:57:46Z

ldennington
Apr 10, 2023
Maintainer

As a heads up, we do have future plans to make use of the password_expiry_utc attribute to improve this workflow. Tracking at #268.

1 reply

DerekSMorin Apr 11, 2023
Author

Thanks @ldennington! I'll subscribe to that one.

This comment was marked as spam.

Sign in to view

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Git credential manager - seems slow to do git push even if there are no changes #1169

{{title}}

Replies: 3 comments 2 replies

{{title}}

{{editor}}'s edit

{{editor}}'s edit

{{title}}

This comment was marked as spam.

{{title}}

{{title}}

Select a reply

Git credential manager - seems slow to do git push even if there are no changes #1169

DerekSMorin Mar 27, 2023

Replies: 3 comments · 2 replies

hickford Mar 30, 2023 Collaborator

DerekSMorin Mar 30, 2023 Author

This comment was marked as spam.

ldennington Apr 10, 2023 Maintainer

DerekSMorin Apr 11, 2023 Author

DerekSMorin
Mar 27, 2023

Replies: 3 comments 2 replies

hickford
Mar 30, 2023
Collaborator

DerekSMorin Mar 30, 2023
Author

ldennington
Apr 10, 2023
Maintainer

DerekSMorin Apr 11, 2023
Author