Bad performance when EnableFileStatusFromCache is true

[Tasteful]

System Details

• posh-git version: 0.7.0
• PowerShell version: 5.1.14393.576
• git version 2.11.0.windows.1
• OS: Microsoft Windows NT 10.0.14393.0
• disc: SSD
• git-status-cache-posh-client: 1.0.0

Issue Description

After installing git-status-cache-posh-client with choco install git-status-cache-posh-client the performance for posh-git is bad and it takes around 5-8 seconds to get the prompt up after any changes in git (ex git add -A or git commit -m "...").

After turning off the git-status-cache with the settings $Global:GitPromptSettings.EnableFileStatusFromCache=$false everything is running fast again and the prompt is up after less than 1 second.

• File structure contains 96975 files, some of them in folder that is excluded in .gitignore.
• the GIT-LFS extension is used that also contains some larger files.

[dahlbyk]

Ping @cmarcusreid. I assume this is an inefficiency in libgit2's status implementation?

@Tasteful: I assume the repo in question is private? Does the cache seem to improve performance on your other repositories?

[Tasteful]

Yes, the repository is private (corporate). I have a smaller repository (also private) whit 18473 files and the performance is worse with git-status-cache-posh-client than without. When I have the cache turned off the prompt is returned directly, when I turn the cache on it takes about 1 second for the prompt to return.

I was setting $Global:GitPromptSettings.DefaultPromptEnableTiming=$true but I didn't get any timing out, do I need to set any other parameter to enable the timing also?

[dahlbyk]

I was setting $Global:GitPromptSettings.DefaultPromptEnableTiming=$true but I didn't get any timing out, do I need to set any other parameter to enable the timing also?

That should be sufficient. Curiously, I am able to reproduce your missing timing in GitHub Desktop's Git Shell, but not in a normal PowerShell window. Odd...

[Tasteful]

That should be sufficient. Curiously, I am able to reproduce your missing timing in GitHub Desktop's Git Shell, but not in a normal PowerShell window. Odd...

I'm using normal PowerShell window, started with Powershell in run-menu. I was testing also from the GitHub Desktop's Git Shell and that have same behavior with bad performance and without timing for me.

[dahlbyk]

Out of curiosity, what does this give you?

gi Function:prompt | select -Exp Definition

I'm guessing it's the old prompt function:

    $realLASTEXITCODE = $LASTEXITCODE

    Write-Host($pwd.ProviderPath) -nonewline

    Write-VcsStatus

    $global:LASTEXITCODE = $realLASTEXITCODE
    return "> "

...or at least a function that doesn't handle $GitPromptSettings.DefaultPromptEnableTiming. It's likely coming in through your $PROFILE, maybe through an old clone's profile.example.ps1?

[Tasteful]

@dahlbyk You was correct. I have copied the profile.example.ps1 into a startup profile that was containing the old prompt-function and after removed that one I get the timings.

And here we have the magic timings.

C:\git [ng1ts ≡ +175 ~1 -0 !] 205ms> $Global:GitPromptSettings.EnableFileStatusFromCache=$false
C:\git [ng1ts ≡ +175 ~1 -0 !] 204ms> git add -A
C:\git [ng1ts ≡ +175 ~1 -0 ~] 249ms> git commit -m "test"
[ng1ts 6c05a67f] test
 176 files changed, 10046 insertions(+), 2 deletions(-)
C:\git [ng1ts ↑1] 249ms> git reset head~1
Unstaged changes after reset:
M       Src/Web/Controllers/Pages/ArticleController.cs
C:\git [ng1ts ≡ +175 ~1 -0 !] 283ms>
C:\git [ng1ts ≡ +175 ~1 -0 !] 283ms> $Global:GitPromptSettings.EnableFileStatusFromCache=$true
C:\git [ng1ts ≡ +175 ~13 -0 !] 11140ms> git add -A
C:\git [ng1ts ≡ +175 ~1 -0 | +0 ~12 -0 !] 11818ms> git commit -m "test"
[ng1ts e07578db] test
 176 files changed, 10046 insertions(+), 2 deletions(-)
C:\git [ng1ts ↑1 +0 ~12 -0 !] 11579ms> git reset head~1
Unstaged changes after reset:
M       Src/Web/Controllers/Pages/ArticleController.cs
C:\git [ng1ts ≡ +175 ~13 -0 !] 11759ms>

[dahlbyk]

Yeah, that's pretty gross. I imagine @cmarcusreid or the libgit2 team would be interested in optimizing this, but it seems unlikely that the issue is with how posh-git is using the cache.

[dahlbyk]

That said, what do you see if you set $Global:GitPromptSettings.Debug=$true?

[Tasteful]

c:\git [ng1ts ≡ +1 ~0 -0 !] 163ms> $Global:GitPromptSettings.Debug=$true
c:\git
VERBOSE: 00004:Getting status
VERBOSE: 00144:Parsing status
VERBOSE: 00145:Status: ## ng1ts...origin/ng1ts
VERBOSE: 00145:Status: ?? js/
VERBOSE: 00146:Building status object
VERBOSE: 00163:Finished
 [ng1ts ≡ +1 ~0 -0 !] 182ms> $GitPromptSettings.DefaultPromptEnableTiming=$true
c:\git
VERBOSE: 00002:Getting status
VERBOSE: 00150:Parsing status
VERBOSE: 00151:Status: ## ng1ts...origin/ng1ts
VERBOSE: 00151:Status: ?? js/
VERBOSE: 00151:Building status object
VERBOSE: 00164:Finished
 [ng1ts ≡ +1 ~0 -0 !] 179ms> $Global:GitPromptSettings.EnableFileStatusFromCache=$false
c:\git
VERBOSE: 00002:Getting status
VERBOSE: 00140:Parsing status
VERBOSE: 00140:Status: ## ng1ts...origin/ng1ts
VERBOSE: 00141:Status: ?? js/
VERBOSE: 00141:Building status object
VERBOSE: 00156:Finished
 [ng1ts ≡ +1 ~0 -0 !] 171ms> git add -A
c:\git
VERBOSE: 00002:Getting status
VERBOSE: 00167:Parsing status
VERBOSE: 00167:Status: ## ng1ts...origin/ng1ts
VERBOSE: 00168:Status: A  js/App/CategoryTeasersEditPanel.d.ts
VERBOSE: 00169:Status: A  js/App/CategoryTeasersEditPanel.js
VERBOSE: 00169:Status: A  js/TS/Typescript/App/CategoryTeasersEditPanel.js
VERBOSE: 00170:Status: A  js/html5shiv.min.js
VERBOSE: 00170:Status: A  js/proj-admin-pages.js
VERBOSE: 00171:Status: A  js/proj-my-pages.js
VERBOSE: 00171:Status: A  js/proj-post.js
VERBOSE: 00172:Status: A  js/proj-pre.js
VERBOSE: 00173:Status: A  js/proj-prod.js
VERBOSE: 00174:Building status object
VERBOSE: 00192:Finished
 [ng1ts ≡ +9 ~0 -0 ~] 206ms> git commit -m "test"
[ng1ts d33c201b] test
 9 files changed, 60391 insertions(+)
c:\git
VERBOSE: 00007:Getting status
VERBOSE: 00223:Parsing status
VERBOSE: 00224:Status: ## ng1ts...origin/ng1ts [ahead 1]
VERBOSE: 00225:Building status object
VERBOSE: 00247:Finished
 [ng1ts ↑1] 273ms> git reset head~1
c:\git
VERBOSE: 00003:Getting status
VERBOSE: 00163:Parsing status
VERBOSE: 00164:Status: ## ng1ts...origin/ng1ts
VERBOSE: 00165:Status: ?? js/
VERBOSE: 00166:Building status object
VERBOSE: 00184:Finished
 [ng1ts ≡ +1 ~0 -0 !] 204ms> $Global:GitPromptSettings.EnableFileStatusFromCache=$true
c:\git
VERBOSE: 00003:Getting status from cache
VERBOSE: 09633:Parsing status
VERBOSE: 09634:Building status object
VERBOSE: 09649:Finished
 [ng1ts ≡ +1 ~12 -0 !] 9669ms> git add -A
c:\git
VERBOSE: 00007:Getting status from cache
VERBOSE: 09756:Parsing status
VERBOSE: 09756:Building status object
VERBOSE: 09770:Finished
 [ng1ts ≡ +9 ~0 -0 | +0 ~12 -0 !] 9794ms> git commit -m "test"
[ng1ts 0262707f] test
 9 files changed, 60391 insertions(+)
c:\git
VERBOSE: 00011:Getting status from cache
VERBOSE: 09503:Parsing status
VERBOSE: 09504:Building status object
VERBOSE: 09520:Finished
 [ng1ts ↑1 +0 ~12 -0 !] 9540ms> git reset head~1
c:\git
VERBOSE: 00003:Getting status from cache
VERBOSE: 10677:Parsing status
VERBOSE: 10678:Building status object
VERBOSE: 10696:Finished
 [ng1ts ≡ +1 ~12 -0 !] 10715ms> 

So the time seams to be in the Getting status from cache

[dahlbyk]

One thing you might try is using PSGit Get-Change to fetch status for this repo. If it takes a similar amount of time as the cache, it's almost certainly an inefficiency in libgit2 rather than the cache.

[cmarcusreid]

Do you see slow perf on cache hits (try pressing enter on the prompt with no Git commands and no file system changes) or only on cache misses?

---

GitStatusCache has optional logging that might provide more information. You can enable it by modifying the Start-Process invocation in Start-GitStatusCache in GitStatusCachePoshClient.ps1 to include

-ArgumentList "--fileLogging --spam"

Reload your shell to reload the profile with the new script, and then call Restart-GitStatusCache. The cache should write a log with a name of form "GitStatusCache_[TIMESTAMP].log" into %TEMP%.

[Tasteful]

@dahlbyk

Result with PSGit version 2.0.4 that is good with timings as posh-git without cache.

PS C:\git> $sw = new-object system.diagnostics.stopwatch
PS C:\git> $sw.reset();$sw.start();get-gitchange;$sw.stop();$sw

Path                                                             Staged Change OldPath
----                                                             ------ ------ -------
js\html5shiv.min.js                                              False  Added
js\app\CategoryTeasersEditPanel.d.ts                    False  Added
js\app\CategoryTeasersEditPanel.js                      False  Added
js\app\Typescript\LitiumStudio\CategoryTeasersEditPanel.js False  Added
js\app-admin-pages.js                                       False  Added
js\app-my-pages.js                                          False  Added
js\app-post.js                                              False  Added
js\app-pre.js                                               False  Added
js\app-prod.js                                              False  Added

IsRunning           : False
Elapsed             : 00:00:00.2701556
ElapsedMilliseconds : 270
ElapsedTicks        : 710679

@cmarcusreid
The slow performance is only when cashe misses happens. If a cache hit the response is faster with status-cache enabled.

Attached is the git status log with three commands.
1 starting and loading the cache for the first time
2 pressing enter
3 adding a new folder with files in the git-repository

GitStatusCache_2017-02-18_09-30-31.0.txt

When I check the c:\git\.git folder I can't find any file or folder that refer to git-status-cache but not sure if the cache is persisting anything to disc.

[cmarcusreid]

Thanks for the log file! The cache is purely in-memory. It will not modify anything in your repository.

The log file shows that the slow performance is at the stage where the cache is making a series of calls to libgit2. GitStatusCache is several releases behind the latest libgit2. I haven't been able to reproduce what you're seeing, but given your PSGit result it's possible that a later version of libgit2 will help. It's also possible GitStatusCache is using a libgit2 function not used by PSGit or that something in GitStatusCache itself is slow on your machine.

I will cut a draft release of GitStatusCache that snaps to the latest libgit2 release and also adds logging to get finer granularity timings so that we can continue to make forward progress if the libgit2 upgrade doesn't help.

[dahlbyk]

🆒 I'm going to go ahead and close this since it doesn't seem to be an issue here. Thanks, @cmarcusreid!

[cmarcusreid]

I've opened cmarcusreid/git-status-cache#21 to continue the disccussion.