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

hasCommand takes over 1s #1085

Closed
1 task done
KyleBastien opened this issue Oct 19, 2021 · 13 comments
Closed
1 task done

hasCommand takes over 1s #1085

KyleBastien opened this issue Oct 19, 2021 · 13 comments
Assignees
@JanDeDobbeleer
Labels
🐛 bug Something isn't working

Comments

@KyleBastien
Copy link

Code of Conduct

  • I agree to follow this project's Code of Conduct

What happened?

oh-my-posh is quite slow on my machine (Windows). I ran the debug tool and opened the log, and it looks like hasCommand is possibly the culprit.

2021/10/19 16:03:02 #### start oh-my-posh run ####
2021/10/19 16:03:02 getenv duration: 0s, args: LOCALAPPDATA
2021/10/19 16:03:02 getCachePath duration: 0s, args: 
2021/10/19 16:03:02 getArgs duration: 0s, args: 
2021/10/19 16:03:02 getArgs duration: 0s, args: 
2021/10/19 16:03:02 getShellName duration: 67.3861ms, args: 
2021/10/19 16:03:02 isRunningAsRoot duration: 0s, args: 
2021/10/19 16:03:02 getcwd duration: 0s, args: 
2021/10/19 16:03:02 getPathSeperator duration: 0s, args: 
2021/10/19 16:03:02 getPathSeperator duration: 0s, args: 
2021/10/19 16:03:02 getPathSeperator duration: 0s, args: 
2021/10/19 16:03:02 getPathSeperator duration: 0s, args: 
2021/10/19 16:03:02 getPathSeperator duration: 0s, args: 
2021/10/19 16:03:02 getPathSeperator duration: 0s, args: 
2021/10/19 16:03:02 getPathSeperator duration: 0s, args: 
2021/10/19 16:03:02 getPathSeperator duration: 0s, args: 
2021/10/19 16:03:02 getPathSeperator duration: 0s, args: 
2021/10/19 16:03:02 getPathSeperator duration: 0s, args: 
2021/10/19 16:03:02 getPathSeperator duration: 0s, args: 
2021/10/19 16:03:02 getPathSeperator duration: 0s, args: 
2021/10/19 16:03:02 getPathSeperator duration: 0s, args: 
2021/10/19 16:03:02 getPathSeperator duration: 0s, args: 
2021/10/19 16:03:02 getPathSeperator duration: 0s, args: 
2021/10/19 16:03:02 getPathSeperator duration: 0s, args: 
2021/10/19 16:03:02 getPathSeperator duration: 0s, args: 
2021/10/19 16:03:02 getPathSeperator duration: 0s, args: 
2021/10/19 16:03:02 getPathSeperator duration: 0s, args: 
2021/10/19 16:03:02 getPathSeperator duration: 0s, args: 
2021/10/19 16:03:02 getPathSeperator duration: 0s, args: 
2021/10/19 16:03:02 getShellName duration: 0s, args: 
2021/10/19 16:03:02 getCurrentUser duration: 0s, args: 
2021/10/19 16:03:02 getHostName duration: 0s, args: 
2021/10/19 16:03:02 getcwd duration: 0s, args: 
2021/10/19 16:03:02 getCurrentUser duration: 0s, args: 
2021/10/19 16:03:02 getRuntimeGOOS duration: 0s, args: 
2021/10/19 16:03:02 getHostName duration: 0s, args: 
2021/10/19 16:03:02 getenv duration: 0s, args: SSH_CONNECTION
2021/10/19 16:03:02 getenv duration: 0s, args: SSH_CLIENT
2021/10/19 16:03:02 getenv duration: 0s, args: POSH_SESSION_DEFAULT_USER
2021/10/19 16:03:02 getcwd duration: 0s, args: 
2021/10/19 16:03:02 getcwd duration: 0s, args: 
2021/10/19 16:03:02 getArgs duration: 0s, args: 
2021/10/19 16:03:02 getcwd duration: 0s, args: 
2021/10/19 16:03:02 getRuntimeGOOS duration: 0s, args: 
2021/10/19 16:03:02 getRuntimeGOOS duration: 0s, args: 
2021/10/19 16:03:02 getPathSeperator duration: 0s, args: 
2021/10/19 16:03:02 getPathSeperator duration: 0s, args: 
2021/10/19 16:03:02 getPathSeperator duration: 0s, args: 
2021/10/19 16:03:02 getPathSeperator duration: 0s, args: 
2021/10/19 16:03:02 getPathSeperator duration: 0s, args: 
2021/10/19 16:03:02 getPathSeperator duration: 0s, args: 
2021/10/19 16:03:02 getPathSeperator duration: 0s, args: 
2021/10/19 16:03:02 getPathSeperator duration: 0s, args: 
2021/10/19 16:03:02 getPathSeperator duration: 0s, args: 
2021/10/19 16:03:02 getPathSeperator duration: 0s, args: 
2021/10/19 16:03:02 getPathSeperator duration: 0s, args: 
2021/10/19 16:03:02 getPathSeperator duration: 0s, args: 
2021/10/19 16:03:02 getPathSeperator duration: 0s, args: 
2021/10/19 16:03:02 getPathSeperator duration: 0s, args: 
2021/10/19 16:03:02 getPathSeperator duration: 0s, args: 
2021/10/19 16:03:02 getPathSeperator duration: 0s, args: 
2021/10/19 16:03:02 getPathSeperator duration: 0s, args: 
2021/10/19 16:03:02 getPathSeperator duration: 0s, args: 
2021/10/19 16:03:02 getPathSeperator duration: 0s, args: 
2021/10/19 16:03:02 getPathSeperator duration: 0s, args: 
2021/10/19 16:03:02 getPathSeperator duration: 0s, args: 
2021/10/19 16:03:02 getPathSeperator duration: 0s, args: 
2021/10/19 16:03:02 getRuntimeGOOS duration: 0s, args: 
2021/10/19 16:03:02 getcwd duration: 0s, args: 
2021/10/19 16:03:03 hasCommand duration: 1.0190253s, args: git
2021/10/19 16:03:03 getcwd duration: 0s, args: 
2021/10/19 16:03:03 hasParentFilePath duration: 0s, args: .git
2021/10/19 16:03:03 getFileContent duration: 551.8µs, args: C:\my-git-repo\.git/HEAD
2021/10/19 16:03:03 getcwd duration: 0s, args: 
2021/10/19 16:03:03 getBatteryInfo duration: 4.8644ms, args: 
2021/10/19 16:03:03 getcwd duration: 0s, args: 
2021/10/19 16:03:03 getcwd duration: 0s, args: 
2021/10/19 16:03:03 getcwd duration: 0s, args: 
2021/10/19 16:03:03 getPathSeperator duration: 0s, args: 
2021/10/19 16:03:03 hasFiles duration: 545.8µs, args: *.js
2021/10/19 16:03:03 getcwd duration: 0s, args: 
2021/10/19 16:03:03 getShellName duration: 0s, args: 
2021/10/19 16:03:03 getcwd duration: 0s, args: 
2021/10/19 16:03:03 isRunningAsRoot duration: 0s, args: 
2021/10/19 16:03:03 getcwd duration: 0s, args: 
2021/10/19 16:03:03 isRunningAsRoot duration: 0s, args: 
2021/10/19 16:03:03 getcwd duration: 0s, args: 
2021/10/19 16:03:03 getPathSeperator duration: 0s, args: 
2021/10/19 16:03:03 getPathSeperator duration: 0s, args: 
2021/10/19 16:03:03 getPathSeperator duration: 0s, args: 
2021/10/19 16:03:03 getPathSeperator duration: 0s, args: 
2021/10/19 16:03:03 getPathSeperator duration: 0s, args: 
2021/10/19 16:03:03 getPathSeperator duration: 0s, args: 
2021/10/19 16:03:03 getPathSeperator duration: 0s, args: 
2021/10/19 16:03:03 getPathSeperator duration: 0s, args: 
2021/10/19 16:03:03 getPathSeperator duration: 0s, args: 
2021/10/19 16:03:03 getPathSeperator duration: 0s, args: 
2021/10/19 16:03:03 getPathSeperator duration: 0s, args: 
2021/10/19 16:03:03 getPathSeperator duration: 0s, args: 
2021/10/19 16:03:03 getPathSeperator duration: 0s, args: 
2021/10/19 16:03:03 getPathSeperator duration: 0s, args: 
2021/10/19 16:03:03 getPathSeperator duration: 0s, args: 
2021/10/19 16:03:03 getPathSeperator duration: 0s, args: 
2021/10/19 16:03:03 getPathSeperator duration: 0s, args: 
2021/10/19 16:03:03 getPathSeperator duration: 0s, args: 
2021/10/19 16:03:03 getPathSeperator duration: 0s, args: 
2021/10/19 16:03:03 getPathSeperator duration: 0s, args: 
2021/10/19 16:03:03 getPathSeperator duration: 0s, args: 
2021/10/19 16:03:03 getShellName duration: 0s, args: 
2021/10/19 16:03:03 getCurrentUser duration: 0s, args: 
2021/10/19 16:03:03 getHostName duration: 0s, args: 
2021/10/19 16:03:03 getcwd duration: 0s, args: 
2021/10/19 16:03:03 lastErrorCode duration: 0s, args: 
2021/10/19 16:03:03 lastErrorCode duration: 0s, args: 
2021/10/19 16:03:03 lastErrorCode duration: 0s, args: 
2021/10/19 16:03:03 #### end oh-my-posh run ####

Any input on why this would be the case? It's also slow on subsequent runs, even though I think hasCommand tries to cache this result.

Version

5.10.1

Theme

aliens

What OS are you seeing the problem on?

Windows

Which shell are you using?

powershell

Relevant log output

No response
@KyleBastien KyleBastien added the 🐛 bug Something isn't working label Oct 19, 2021
@JanDeDobbeleer
Copy link
Owner

@KyleBastien we've only seen this once (also with git) where the executable was mapped to something else (it picked up a shell script rather than an executable).

@KyleBastien
Copy link
Author

@JanDeDobbeleer maybe I'm being daft here, by executable here do you meant the git executable or the oh-my-posh executable?

@JanDeDobbeleer
Copy link
Owner

The git executable (that's the which seems to take a long time).

@JanDeDobbeleer
Copy link
Owner

@KyleBastien I'm going to add some logging so we can see what's going on.

JanDeDobbeleer added a commit that referenced this issue Oct 20, 2021
@JanDeDobbeleer
feat: environment error logging
bc2ad2f 
relates to #1085
JanDeDobbeleer added a commit that referenced this issue Oct 20, 2021
@JanDeDobbeleer
feat: environment error logging
4ae4fa6 
relates to #1085
@JanDeDobbeleer JanDeDobbeleer mentioned this issue Oct 20, 2021
Merged
4 tasks
JanDeDobbeleer added a commit that referenced this issue Oct 20, 2021
@JanDeDobbeleer
feat: environment error logging
94b743c 
relates to #1085
@JanDeDobbeleer
Copy link
Owner

@KyleBastien with the latest release, can you run the debug again and share the logs?

@KyleBastien
Copy link
Author

@JanDeDobbeleer Thanks for the help here! On v5.12.0 I see this:

2021/10/20 09:17:07 #### start oh-my-posh run ####
2021/10/20 09:17:07 getenv duration: 0s, args: LOCALAPPDATA
2021/10/20 09:17:07 getCachePath duration: 0s, args: 
2021/10/20 09:17:07 getArgs duration: 0s, args: 
2021/10/20 09:17:07 getArgs duration: 0s, args: 
2021/10/20 09:17:07 getShellName duration: 83.8321ms, args: 
2021/10/20 09:17:07 isRunningAsRoot duration: 0s, args: 
2021/10/20 09:17:07 getcwd duration: 0s, args: 
2021/10/20 09:17:07 getPathSeperator duration: 0s, args: 
2021/10/20 09:17:07 getPathSeperator duration: 0s, args: 
2021/10/20 09:17:07 getShellName duration: 0s, args: 
2021/10/20 09:17:07 getCurrentUser duration: 0s, args: 
2021/10/20 09:17:07 getHostName duration: 0s, args: 
2021/10/20 09:17:07 getcwd duration: 0s, args: 
2021/10/20 09:17:07 getCurrentUser duration: 0s, args: 
2021/10/20 09:17:07 getRuntimeGOOS duration: 0s, args: 
2021/10/20 09:17:07 getHostName duration: 0s, args: 
2021/10/20 09:17:07 getenv duration: 0s, args: SSH_CONNECTION
2021/10/20 09:17:07 getenv duration: 0s, args: SSH_CLIENT
2021/10/20 09:17:07 getenv duration: 0s, args: POSH_SESSION_DEFAULT_USER
2021/10/20 09:17:07 getcwd duration: 0s, args: 
2021/10/20 09:17:07 getcwd duration: 0s, args: 
2021/10/20 09:17:07 getArgs duration: 0s, args: 
2021/10/20 09:17:07 getcwd duration: 0s, args: 
2021/10/20 09:17:07 getRuntimeGOOS duration: 0s, args: 
2021/10/20 09:17:07 getRuntimeGOOS duration: 0s, args: 
2021/10/20 09:17:07 getPathSeperator duration: 0s, args: 
2021/10/20 09:17:07 getPathSeperator duration: 0s, args: 
2021/10/20 09:17:07 getPathSeperator duration: 0s, args: 
2021/10/20 09:17:07 getRuntimeGOOS duration: 0s, args: 
2021/10/20 09:17:07 getcwd duration: 0s, args: 
2021/10/20 09:17:08 hasCommand duration: 972.7541ms, args: git
2021/10/20 09:17:08 getcwd duration: 0s, args: 
2021/10/20 09:17:08 error: CreateFile C:\.git: The system cannot find the file specified.
2021/10/20 09:17:08 hasParentFilePath duration: 0s, args: .git
2021/10/20 09:17:08 getcwd duration: 0s, args: 
2021/10/20 09:17:08 getBatteryInfo duration: 4.8623ms, args: 
2021/10/20 09:17:08 getcwd duration: 0s, args: 
2021/10/20 09:17:08 getcwd duration: 0s, args: 
2021/10/20 09:17:08 getcwd duration: 0s, args: 
2021/10/20 09:17:08 getShellName duration: 0s, args: 
2021/10/20 09:17:08 getcwd duration: 0s, args: 
2021/10/20 09:17:08 isRunningAsRoot duration: 510.1µs, args: 
2021/10/20 09:17:08 getcwd duration: 0s, args: 
2021/10/20 09:17:08 isRunningAsRoot duration: 0s, args: 
2021/10/20 09:17:08 getcwd duration: 0s, args: 
2021/10/20 09:17:08 getPathSeperator duration: 0s, args: 
2021/10/20 09:17:08 getPathSeperator duration: 0s, args: 
2021/10/20 09:17:08 getShellName duration: 0s, args: 
2021/10/20 09:17:08 getCurrentUser duration: 0s, args: 
2021/10/20 09:17:08 getHostName duration: 0s, args: 
2021/10/20 09:17:08 getcwd duration: 0s, args: 
2021/10/20 09:17:08 lastErrorCode duration: 0s, args: 
2021/10/20 09:17:08 lastErrorCode duration: 0s, args: 
2021/10/20 09:17:08 lastErrorCode duration: 0s, args: 
2021/10/20 09:17:08 #### end oh-my-posh run ####

Looks like maybe this error is related?

2021/10/20 09:17:08 error: CreateFile C:.git: The system cannot find the file specified.

@JanDeDobbeleer
Copy link
Owner

@KyleBastien that comes from hasParentFilePath, it strikes me as odd that hasCommand does not error. It simply takes this long. Do you perhaps have quite significant folders on your PATH?

@KyleBastien
Copy link
Author

@JanDeDobbeleer I have ~66 folders in PATH by the looks of it. That doesn't seem like that many?

But I can see that if I move C:\Program Files\Git\cmd; to the beginning of my PATH, the performance for this is much better (basically instant). So this must have to do with the number of folders I have in PATH.

2021/10/20 10:54:17 #### start oh-my-posh run ####
2021/10/20 10:54:17 getenv duration: 0s, args: LOCALAPPDATA
2021/10/20 10:54:17 getCachePath duration: 0s, args: 
2021/10/20 10:54:17 getArgs duration: 0s, args: 
2021/10/20 10:54:17 getArgs duration: 0s, args: 
2021/10/20 10:54:17 getShellName duration: 67.4527ms, args: 
2021/10/20 10:54:17 isRunningAsRoot duration: 49.4µs, args: 
2021/10/20 10:54:17 getcwd duration: 0s, args: 
2021/10/20 10:54:17 getPathSeperator duration: 0s, args: 
2021/10/20 10:54:17 getPathSeperator duration: 0s, args: 
2021/10/20 10:54:17 getShellName duration: 0s, args: 
2021/10/20 10:54:17 getCurrentUser duration: 0s, args: 
2021/10/20 10:54:17 getHostName duration: 0s, args: 
2021/10/20 10:54:17 getcwd duration: 0s, args: 
2021/10/20 10:54:17 getCurrentUser duration: 0s, args: 
2021/10/20 10:54:17 getRuntimeGOOS duration: 0s, args: 
2021/10/20 10:54:17 getHostName duration: 67.3µs, args: 
2021/10/20 10:54:17 getenv duration: 0s, args: SSH_CONNECTION
2021/10/20 10:54:17 getenv duration: 0s, args: SSH_CLIENT
2021/10/20 10:54:17 getenv duration: 0s, args: POSH_SESSION_DEFAULT_USER
2021/10/20 10:54:17 getcwd duration: 0s, args: 
2021/10/20 10:54:17 getcwd duration: 0s, args: 
2021/10/20 10:54:17 getArgs duration: 0s, args: 
2021/10/20 10:54:17 getcwd duration: 0s, args: 
2021/10/20 10:54:17 getRuntimeGOOS duration: 0s, args: 
2021/10/20 10:54:17 getRuntimeGOOS duration: 0s, args: 
2021/10/20 10:54:17 getPathSeperator duration: 0s, args: 
2021/10/20 10:54:17 getPathSeperator duration: 0s, args: 
2021/10/20 10:54:17 getPathSeperator duration: 0s, args: 
2021/10/20 10:54:17 getRuntimeGOOS duration: 0s, args: 
2021/10/20 10:54:17 getcwd duration: 0s, args: 
2021/10/20 10:54:17 hasCommand duration: 1.6439ms, args: git
2021/10/20 10:54:17 getcwd duration: 0s, args: 
2021/10/20 10:54:17 error: CreateFile C:\.git: The system cannot find the file specified.
2021/10/20 10:54:17 hasParentFilePath duration: 556.1µs, args: .git
2021/10/20 10:54:17 getcwd duration: 0s, args: 
2021/10/20 10:54:17 getBatteryInfo duration: 3.9676ms, args: 
2021/10/20 10:54:17 getcwd duration: 0s, args: 
2021/10/20 10:54:17 getcwd duration: 0s, args: 
2021/10/20 10:54:17 getcwd duration: 0s, args: 
2021/10/20 10:54:17 getShellName duration: 0s, args: 
2021/10/20 10:54:17 getcwd duration: 0s, args: 
2021/10/20 10:54:17 isRunningAsRoot duration: 0s, args: 
2021/10/20 10:54:17 getcwd duration: 0s, args: 
2021/10/20 10:54:17 isRunningAsRoot duration: 0s, args: 
2021/10/20 10:54:17 getcwd duration: 0s, args: 
2021/10/20 10:54:17 getPathSeperator duration: 0s, args: 
2021/10/20 10:54:17 getPathSeperator duration: 0s, args: 
2021/10/20 10:54:17 getShellName duration: 0s, args: 
2021/10/20 10:54:17 getCurrentUser duration: 0s, args: 
2021/10/20 10:54:17 getHostName duration: 0s, args: 
2021/10/20 10:54:17 getcwd duration: 0s, args: 
2021/10/20 10:54:17 lastErrorCode duration: 0s, args: 
2021/10/20 10:54:17 lastErrorCode duration: 0s, args: 
2021/10/20 10:54:17 lastErrorCode duration: 0s, args: 
2021/10/20 10:54:17 #### end oh-my-posh run ####

Going to close, since this looks to be a me problem. Thank you so much for you help on this @JanDeDobbeleer!

@JanDeDobbeleer
Copy link
Owner

I only figured out this possibility by looking at go's source code. It's an interesting piece to debug as there could be quite a bit of optimizations to be done on Windows from oh-my-posh.

@KyleBastien
Copy link
Author

@JanDeDobbeleer it might be faster (more consistently) just to exec git and see if it errors? If it does error, then you can assume git is not installed?

@JanDeDobbeleer
Copy link
Owner

@KyleBastien there was an issue with git on Windows where the command cache was't correctly set. When you run Command it will always do LookPath anyways which is why we built the command cache so we already have the full path to an executable which then effectively skips LookPath when running a command. Running the command directly does not give you that advantage.

@KyleBastien
Copy link
Author

Running the command directly does not give you that advantage.

Ahh that makes sense. Yes I can see the advantage of just doing the current method. After moving the folder in my path and now upgrading to 5.12.1 this is basically instant now. Really appreciate your help on this @JanDeDobbeleer!

@github-actions GitHub Actions
Copy link

github-actions bot commented Apr 1, 2024

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.

@github-actions github-actions bot locked as resolved and limited conversation to collaborators Apr 1, 2024
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Assignees

@JanDeDobbeleer JanDeDobbeleer

Labels
🐛 bug Something isn't working
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@JanDeDobbeleer @KyleBastien