search

JanDeDobbeleer / oh-my-posh

The most customisable and low-latency cross platform/shell prompt renderer
https://ohmyposh.dev
MIT License
16.79k stars 2.35k forks source link

Performance: Command execution slow on Windows #305

Closed amoldeshpande closed 3 years ago

amoldeshpande commented 3 years ago

Prerequisites

Description

Slowness in rendering prompt. It's noticeably slow in Windows compared to WSL2, even in the same Terminal.

Environment

Steps to Reproduce

I was trying to figure out why composing the prompt is so slow on windows. I unfortunately don't know much go, but I muddled around with it and found a couple of things.

Firstly, running and parsing git commands seems quite slow.

PS C:\Users\amol> Measure-Command {posh-windows-amd64.exe --shell zsh --config c:\users\amol\.poshthemes\amol.omp.json}

Days              : 0
Hours             : 0
Minutes           : 0
Seconds           : 0
Milliseconds      : 89
Ticks             : 895987
TotalDays         : 1.03702199074074E-06
TotalHours        : 2.48885277777778E-05
TotalMinutes      : 0.00149331166666667
TotalSeconds      : 0.0895987
TotalMilliseconds : 89.5987

PS C:\Users\amol> Measure-Command {c:\users\amol\appdata\local\Atlassian\SourceTree\git_local\bin\git.exe rev-parse --is-inside-work-tree }
fatal: Not a git repository (or any of the parent directories): .git

Days              : 0
Hours             : 0
Minutes           : 0
Seconds           : 0
Milliseconds      : 37
Ticks             : 376365
TotalDays         : 4.35607638888889E-07
TotalHours        : 1.04545833333333E-05
TotalMinutes      : 0.000627275
TotalSeconds      : 0.0376365
TotalMilliseconds : 37.6365

As you can see here, running the raw git command takes less than half the time it takes to run a posh command where my only config is a git segment (the default one from your theme file)

There is no git repo in that directory (I was trying to get the fastest execution for the git segment, but interestingly the overall execution time of posh does not change even within a git repo)

I tried to do some profiling in go, and came up with this for execution:

I'm always running 

posh-windows-amd64.exe --shell zsh --config c:\users\amol\.poshthemes\amol.omp.json

where the theme only contains a only git prompt segment exactly like the jandedobbeleer profile

H:\github\oh-my-posh3\src>go tool pprof c:\Users\amol\foo
Type: cpu
Time: Jan 1, 2021 at 2:20pm (PST)
Duration: 201.11ms, Total samples = 60ms (29.83%)
Entering interactive mode (type "help" for commands, "o" for options)
(pprof) top10
Showing nodes accounting for 60ms, 100% of 60ms total
Showing top 10 nodes out of 30
      flat  flat%   sum%        cum   cum%
      50ms 83.33% 83.33%       50ms 83.33%  runtime.cgocall
      10ms 16.67%   100%       10ms 16.67%  os/exec.(*Cmd).Start
         0     0%   100%       30ms 50.00%  bufio.(*Reader).ReadLine
         0     0%   100%       30ms 50.00%  bufio.(*Reader).ReadSlice
         0     0%   100%       30ms 50.00%  bufio.(*Reader).fill
         0     0%   100%       30ms 50.00%  internal/poll.(*FD).Read
         0     0%   100%       60ms   100%  main.(*Segment).enabled (inline)
         0     0%   100%       60ms   100%  main.(*Segment).setStringValue
         0     0%   100%       60ms   100%  main.(*engine).setStringValues.func1
         0     0%   100%       10ms 16.67%  main.(*environment).hasCommand
(pprof) quit

In a repo with git, this is the profile

H:\github\oh-my-posh3\src>go tool pprof foo
Type: cpu
Time: Jan 1, 2021 at 2:08pm (PST)
Duration: 412.02ms, Total samples = 220ms (53.40%)
Entering interactive mode (type "help" for commands, "o" for options)
(pprof) top10
Showing nodes accounting for 220ms, 100% of 220ms total
Showing top 10 nodes out of 48
      flat  flat%   sum%        cum   cum%
     210ms 95.45% 95.45%      210ms 95.45%  runtime.cgocall
      10ms  4.55%   100%       10ms  4.55%  runtime.slicerunetostring
         0     0%   100%      150ms 68.18%  bufio.(*Reader).ReadLine
         0     0%   100%      150ms 68.18%  bufio.(*Reader).ReadSlice
         0     0%   100%      150ms 68.18%  bufio.(*Reader).fill
         0     0%   100%       30ms 13.64%  fmt.Fprintf
         0     0%   100%       30ms 13.64%  fmt.Printf
         0     0%   100%      150ms 68.18%  internal/poll.(*FD).Read
         0     0%   100%       30ms 13.64%  internal/poll.(*FD).Write
         0     0%   100%       30ms 13.64%  internal/poll.(*FD).writeConsole
(pprof)

So, it seems that running multiple git commands slows things down even more , as you'd expect.

With my less-than-zero knowledge of go, I can only theorize that

  1. Perhaps parallelizing all the git commands will help responsiveness, instead of executing them sequentially. I saw a closed issue where you did this for segments, but I wasn't able to figure out if you tried just the git commands.
  2. Maybe there is an optimization to be made where instead of reading line by line, you read the entire buffer and then parse it line by line. This should help in situations where there is a lot of git output, I would think.

Love the tool, thanks for the great work !

amoldeshpande commented 2 years ago

Well I don’t think the static build will do anything unless the go linker explicitly links with all the Windows import libraries it needs. Static builds are meaningless in windows except for the c library, which i assume go doesn’t need anyway.

A normal, well behaved windows application will link with system import libs for kernel32 user32 advapi32 ws2_32 etc. when such an application starts, the NT loader will in current versions load the DLLS for these in parallel.

what go did the last time I looked at it, was that in a stupid overkill aim to only ship an exe (again, static is meaningless in windows), they didn’t link with any system libs and instead serially loaded each one at startup.

maybe it has changed, but only a WPT profile will tell

apapiccio commented 2 years ago

The slow load times I was experiencing turned out to be MS Defender ATP in the end. for whatever reason it was causing some intensive scanning. After we reported this to MS Support the following day we saw Defender ATP no longer was blatting it and the prompt profile came up in the expected time.

All back to normal now.

thomasmuders-imtf commented 2 years ago

@apapiccio Thank you for reporting this to Microsoft! So it turns out for me the culprit was also Defender ATP as today, it is behaving normally again! ❤

github-actions[bot] commented 7 months ago

This issue has been automatically locked since there has not been any recent activity (i.e. last half year) after it was closed. It helps our maintainers focus on the active issues. If you have found a problem that seems similar, please open a discussion first, complete the body with all the details necessary to reproduce, and mention this issue as reference.