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.

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

Searching for Chocolatey packages very slow #248

Closed
c6p opened this issue Dec 17, 2019 · 31 comments · Fixed by #321
Closed

Searching for Chocolatey packages very slow #248

c6p opened this issue Dec 17, 2019 · 31 comments · Fixed by #321
Labels

Comments

@c6p
Copy link
Contributor

c6p commented Dec 17, 2019

If I disable searching for chocolatey packages, startup time is acceptable. But with chocolatey enabled it is very slow and sometimes hangs at startup.

Version: 4.15.0.42702
Chocolatey v0.10.15
Windows 10 Pro - version 1909, build 18363.535

@Klocman
Copy link
Owner

Klocman commented Dec 20, 2019

What happens if you run choco list -l -nocolor -y -r in cmd? Is it slow?

@c6p
Copy link
Contributor Author

c6p commented Dec 21, 2019

No. It took about 3 seconds when cold and about 1 second when warm. While BCU search for chocolatey packages tooks somewhere around a minute.

@Klocman
Copy link
Owner

Klocman commented Dec 21, 2019 via email

@c6p
Copy link
Contributor Author

c6p commented Dec 24, 2019

Yes, I have Visual Studio and have experience in debugging, but not any in profiling with it though. I am going to build a debug version of BCU tomorrow, and then try profiling. Is there anything I should know?

@Klocman
Copy link
Owner

Klocman commented Dec 24, 2019 via email

@c6p
Copy link
Contributor Author

c6p commented Dec 28, 2019

I couldn't build it. I have VS 2019, got the kloctools and build successfully. Now UninstallTools fails with the following. I checked the documentation and it seems these methods do not exist.

8>C:\Users\can\_work\temp\Bulk-Crap-Uninstaller\source\UninstallTools\Junk\Finders\Drive\CommonDriveJunkScanner.cs(57,70,57,93): error CS1061: 'DirectoryInfo' does not contain a definition for 'GetNameWithoutExtension' and no accessible extension method 'GetNameWithoutExtension' accepting a first argument of type 'DirectoryInfo' could be found (are you missing a using directive or an assembly reference?)
8>C:\Users\can\_work\temp\Bulk-Crap-Uninstaller\source\UninstallTools\Junk\Finders\Drive\CommonDriveJunkScanner.cs(88,157,88,180): error CS1061: 'FileSystemInfo' does not contain a definition for 'GetNameWithoutExtension' and no accessible extension method 'GetNameWithoutExtension' accepting a first argument of type 'FileSystemInfo' could be found (are you missing a using directive or an assembly reference?)

Both v4.15 and master fails on me.

@Klocman
Copy link
Owner

Klocman commented Dec 28, 2019 via email

@c6p
Copy link
Contributor Author

c6p commented Dec 28, 2019

Thanks. That was fast. It builds now.

Here it is. I am looking into it too, but I couldn't figure anything out of it.
Report.zip

@Klocman
Copy link
Owner

Klocman commented Dec 28, 2019 via email

@c6p
Copy link
Contributor Author

c6p commented Dec 28, 2019

With a debug build I still cannot see source code from other projects (i.e. Uninstall Tools). I played around but couldn't find a way, project properties shows debug:full selected.
Debug-with_chocolatey.zip

@Klocman
Copy link
Owner

Klocman commented Jan 23, 2020

I added some performance logging in recent commits, it should help narrow the issue if you still have it. The changes will be included in the upcoming update. The logs are written to the log file inside BCU directory.

@Klocman
Copy link
Owner

Klocman commented Jan 26, 2020

It looks like it's Chocolatey being slow after all. The issue is that it's difficult to test this because it's slow only the first time it scans for the applications, no matter if it's triggered by BCU or manually by command line. Then other times it's randomly very slow when started from command line.

So far it looks like the issue is on the Chocolatey side, assuming it's not just normal operation that takes time.

If you can confirm that running choco list from command line after a fresh system boot is slow I'll close the issue since it should be opened on the chocolatey repository instead.

@c6p
Copy link
Contributor Author

c6p commented Jan 27, 2020

  • choco list, cold 01:03.101 -- about a minute after reboot
  • choco list, warm 01:01.222 -- subsequent runs still slow
  • choco list -l -nocolor -y -r, cold 00:05.859 - less than 6 seconds immediately after reboot
  • choco list -l -nocolor -y -r, warm 00:01.177 - then consistently about a second

There may be a problem on Chocolatey side. However, It is never slow for me when run with --localonly. So I think it should not be slow when called from BCU.

@Klocman
Copy link
Owner

Klocman commented Jan 27, 2020 via email

@c6p
Copy link
Contributor Author

c6p commented May 18, 2020

... It has to then ask for details for all applications, so maybe that's where it gets slow.

Yes, that is where it gets slow. Thank you, extended logging is very useful. As you can see every chocolatey command took over a second. Totaling up to a nearly 2 minutes of time with many packages.

...
7:22:31 - [Performance] Running command C:\ProgramData\chocolatey\bin\choco.exe info -l -nocolor -y -v windirstat took 1235ms
7:22:31 - [Performance] Factory Searching for Chocolatey packages took 109939ms to finish

It seems chocolatey has a --detail flag. Below command took 1447ms for me, and retrieves all the information gathered in 110 seconds with a single command.

choco.exe list -lo -nocolor -detail

@Klocman Klocman added the bug label May 6, 2021
@zbalkan
Copy link
Contributor

zbalkan commented Sep 21, 2021

I'm thinking about utilizing the chocolatey.lib library so that it would be possible to get rid of parsing. However, it would add dependency of chocolatey.lib and related log4net. Is it okay for you?

@Klocman
Copy link
Owner

Klocman commented Sep 28, 2021 via email

@zbalkan
Copy link
Contributor

zbalkan commented Sep 28, 2021

Well, I wrote a benchmark application to compare ChocolateyFactory class with the one I wrote using chocolatey.lib. The difference is so high, I believe there is something wrong with it. However, I did not check the size difference with the new dependencies.

Also, when I use BCUninstaller, it takes more than 4 minutes to query all chocolatey installations -currently 68 packages. That's why I felt the urge to improve the query performance. Process creation overhead is really a PITA.

By the way, you can give my Benchmark Repo a shot for performance issues. It would be great to get a review from you.
https://github.com/zbalkan/BenchmarkChoco

@c6p
Copy link
Contributor Author

c6p commented Sep 28, 2021

@Klocman why not try choco.exe list -lo -nocolor -detail I mentioned before. I think it already solves the problem without additional dependencies. It requests all details in a single call when listing packages, no need to call detail for each package explicitly.

Possibly it would not be as fast as utilizing chocolatey.lib, but it would be very close, since there is no separate call to chocolatey for a hundred packages.

@zbalkan
Copy link
Contributor

zbalkan commented Sep 28, 2021

@c6p, maybe you can run a benchmark or even send a PR. It would be nice to see the difference.

And yes, removing the overhead of process creation makes a difference almost every time.

@c6p
Copy link
Contributor Author

c6p commented Sep 29, 2021

@zbalkan since my comment in May 2020, I have switched over to scoop from chocolatey. Seeing your discussion I decided to chime in.

I will try to make a PR, though I cannot benchmark it anymore. I will let you know when I've made the changes in my repo, could you benchmark both?

@zbalkan
Copy link
Contributor

zbalkan commented Sep 29, 2021

@c6p Of course, if you send a PR, I could try it.

c6p added a commit to c6p/Bulk-Crap-Uninstaller that referenced this issue Oct 1, 2021
@c6p
Copy link
Contributor Author

c6p commented Oct 1, 2021

@zbalkan sorry for the wait, I just found the time. Here it is, could you benchmark it?

@zbalkan
Copy link
Contributor

zbalkan commented Oct 1, 2021

@c6p That's great. But I don't have access to my laptop right now. I might try tomorrow. However, you can check my benchmark project. You can do that yourself too since it will cover %80 of your use case. You can find the link above.

@c6p
Copy link
Contributor Author

c6p commented Oct 1, 2021

@zbalkan Since I do not use chocolatey anymore, I don't have many packages, I have installed 2 to test, choco lists 5 packages.

Thanks for the benchmark, it is very nice. Single call strategy is not as fast as library strategy as expected, but I think it is pretty acceptable, since quite possibly it will run under a second, irrespective of number of packages a user has.

Method Mean Error StdDev Median
ParsingExecutableOutputStrategy 4,617.64 ms 154.509 ms 455.573 ms 4,316.96 ms
UsingLibraryStrategy 28.74 ms 0.968 ms 2.854 ms 27.87 ms
ParsingSingleStrategy 742.68 ms 3.356 ms 9.895 ms 739.61 ms

Your benchmark would give us a better idea of trade-offs.

@zbalkan
Copy link
Contributor

zbalkan commented Oct 3, 2021

@c6p The benchmark takes about 10 hours and here are the latest results.

BenchmarkDotNet=v0.13.1, OS=Windows 10.0.18363.1801 (1909/November2019Update/19H2)
AMD A10-9600P RADEON R5, 10 COMPUTE CORES 4C+6G, 1 CPU, 4 logical and 4 physical cores
  [Host]     : .NET Framework 4.8 (4.8.4400.0), X64 RyuJIT  [AttachedDebugger]
  Job-AJPCRR : .NET Framework 4.8 (4.8.4400.0), X64 RyuJIT

IterationCount=100  LaunchCount=1  RunStrategy=Monitoring  
WarmupCount=5  
Method Mean Error StdDev Median
ParsingExecutableOutputStrategy 339,615.4 ms 7,150.17 ms 21,082.43 ms 322,660.8 ms
UsingLibraryStrategy 679.2 ms 20.87 ms 61.54 ms 697.2 ms
ParsingSingleStrategy 6,021.2 ms 116.28 ms 342.86 ms 6,091.6 ms

@c6p
Copy link
Contributor Author

c6p commented Oct 3, 2021

@zbalkan Thank you. Now @Klocman has to decide which approach to take.

@zbalkan
Copy link
Contributor

zbalkan commented Oct 4, 2021

@c6p You probably need to make a PR. Although my method has significant improvement in time, the chocolatey.lib adds some odd complexities that occur time to time, which can be called Heisenbug. I need to check the actual problem and probably make the PR to Chocolatey repository first.

Your suggestion is simpler and smooth.

@c6p
Copy link
Contributor Author

c6p commented Oct 4, 2021

@zbalkan Done.

Though, your solution does not depend on output of another program and may be more stable in the long term if you can resolve the issues.

@zbalkan
Copy link
Contributor

zbalkan commented Oct 6, 2021

It turns out that the problem is about the target frameworks, as mentioned in the chocolatey/choco#2393. Bulk Crap Uninstaller targets dotnet 5 while Chocolatey targets 4.

My solution is not available until chocolatey.lib is upgraded, meaning that the PR by @c6p is the only applicable solution for now.

Klocman pushed a commit that referenced this issue Oct 11, 2021
@Klocman
Copy link
Owner

Klocman commented Oct 11, 2021

Thank you! I'll take c6p's solution for now since it's already a big improvement. If using chocolatey.lib becomes viable in the future then we can switch to that if need be.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Projects
None yet
Development

Successfully merging a pull request may close this issue.

3 participants