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

brew update can be terribly slow for stale taps #13224

Closed
2 tasks done
boblail opened this issue May 2, 2022 · 2 comments
Closed
2 tasks done

brew update can be terribly slow for stale taps #13224

boblail opened this issue May 2, 2022 · 2 comments
Labels
bug Reproducible Homebrew/brew bug help wanted We want help addressing this outdated PR was locked due to age

Comments

@boblail
Copy link
Contributor

boblail commented May 2, 2022

brew config output

HOMEBREW_VERSION: 3.4.10-3-gbb3d970-dirty
ORIGIN: https://github.com/Homebrew/brew
HEAD: bb3d97030c68ed6d3074b4689a39a0ebb556fbf4
Last commit: 6 hours ago
Core tap ORIGIN: https://github.com/Homebrew/homebrew-core
Core tap HEAD: dbc32b7ea38309f8b0b91e9f1ecf68e17c8a519d
Core tap last commit: 8 minutes ago
Core tap branch: master
HOMEBREW_PREFIX: /usr/local
HOMEBREW_CASK_OPTS: []
HOMEBREW_CORE_GIT_REMOTE: https://github.com/Homebrew/homebrew-core
HOMEBREW_MAKE_JOBS: 16
HOMEBREW_NO_ANALYTICS: set
Homebrew Ruby: 2.6.8 => /System/Library/Frameworks/Ruby.framework/Versions/2.6/usr/bin/ruby
CPU: 16-core 64-bit kabylake
Clang: 13.1.6 build 1316
Git: 2.35.1 => /usr/local/bin/git
Curl: 7.79.1 => /usr/bin/curl
macOS: 12.3.1-x86_64
CLT: 13.3.0.0.1.1645755326
Xcode: N/A

brew doctor output

Please note that these warnings are just used to help the Homebrew maintainers
with debugging if you file an issue. If everything you use Homebrew for is
working fine: please don't worry or file an issue; just ignore this. Thanks!

Warning: Some installed formulae are deprecated or disabled.
You should find replacements for the following formulae:
  bazaar

Warning: You have unlinked kegs in your Cellar.
Leaving kegs unlinked can lead to build-trouble and cause formulae that depend on
those kegs to fail to run properly once built. Run `brew link` on these:
  kubernetes-cli

Warning: You have uncommitted modifications to Homebrew/brew.
If this is a surprise to you, then you should stash these modifications.
Stashing returns Homebrew to a pristine state but can be undone
should you later need to do so for some reason.
  cd /usr/local/Homebrew && git stash && git clean -d -f

Uncommitted files:
   M Library/Homebrew/cmd/update-report.rb
   M Library/Homebrew/cmd/update.sh

Verification

  • I ran brew update and am still able to reproduce my issue.
  • I have resolved all warnings from brew doctor and that did not fix my problem.

What were you trying to do (and why)?

If you run brew update on a very stale tap, the update-report takes a long time.

For example,

git -C "$(brew --repo homebrew/core)" reset --hard e27948a0f03 # commit on master from Dec 2021
time brew update

takes 2m40s on my MacBook Pro (2.3 GHz 8-Core Intel Core i9)

If I comment out just the call to brew update-report, the same operation takes 3.8s — so the expense is entirely in brew update-report.

Alternately, if I comment out just lines 373-383 in update-report.rb, the same operation takes 10.3s.

brew update --preinstall also bypasses these lines; but it cuts corners in update.sh as well.

What happened (include all command output)?

(Described above)

What did you expect to happen?

I would expect brew update not to take minutes, even for stale taps

Step-by-step reproduction instructions (by running brew commands)

(Described above)
@boblail boblail added the bug Reproducible Homebrew/brew bug label May 2, 2022
boblail added a commit to boblail/brew that referenced this issue May 2, 2022
…update`

Why?
====
When humans run `brew update`, the update report is helpful feedback; but when `brew update` is composed into other scripts, the update report is rarely useful.

Scripts could always capture or discard its output (we've been capturing it and displaying it only when `brew update` fails), but since generating the update report can be very expensive (Homebrew#13224), this seems like a lot of wasted effort.

This solution differs from `--preinstall` in two important ways where `--preinstall`'s behavior is undesirable:
1. `--preinstall` limits but still produces the update report
2. `--preinstall` takes several shortcuts in `brew update`, softening its guarantees
@MikeMcQuaid
Copy link
Member

Will review and consider accepting a PR that either:

  • maintains current functionality and speeds this up
  • removes this behaviour entirely and has another maintainer than just me agree with it

@MikeMcQuaid MikeMcQuaid added the help wanted We want help addressing this label May 2, 2022
boblail added a commit to boblail/brew that referenced this issue May 2, 2022
…update`

Why?
====
When humans run `brew update`, the update report is helpful feedback; but when `brew update` is composed into other scripts, the update report is rarely useful.

Scripts could always capture or discard its output (we've been capturing it and displaying it only when `brew update` fails), but since generating the update report can be very expensive (Homebrew#13224), this seems like a lot of wasted effort.

This solution differs from `--preinstall` in two important ways where `--preinstall`'s behavior is undesirable:
1. `--preinstall` limits but still produces the update report
2. `--preinstall` takes several shortcuts in `brew update`, softening its guarantees
boblail added a commit to boblail/brew that referenced this issue May 4, 2022
`brew update` fast-forwards each tap from one commit to another.

`update-report` lists all the formulae that were modified in that commit range.

This clause was filtering out modified formulae _whose `pkg_version` had not changed._

The outcome of this filtering:

- If you rewind homebrew/core **2,000 commits** (or 2 weeks), **819** formulae were modified. This clause would have filtered out **153** (18.7%) of them whose `pkg_version` had not changed. It would've taken **29.0 seconds**.

- If you rewind homebrew/core **20,000 commits** (or 5 months), 3532 formulae were modified. This clause would have filtered out 1121 (31.7%) of them whose `pkg_version` had not changed. It would've taken **119.4 seconds**.

| Branch | Command | Commits | Time | Modified |
| --- | --- | --- | --- |
| `master` | `git -C "$(brew --repo homebrew/core)" reset --hard aa1b3d5; time sh -c "brew update &> output-2k.txt"` | 2,000 | 35.6s | 666 |
| `master` | `git -C "$(brew --repo homebrew/core)" reset --hard 11e6919; time sh -c "brew update &> output-20k.txt"` | 20,000 | 129.8s | 2411 |
| `lail/xyz` | `git -C "$(brew --repo homebrew/core)" reset --hard aa1b3d5; time sh -c "brew update &> output-2k.txt"` | 2,000 | 6.6s | 819 |
| `lail/xyz` | `git -C "$(brew --repo homebrew/core)" reset --hard 11e6919; time sh -c "brew update &> output-20k.txt"` | 20,000 | 10.4s | 3532 |

This operation was so expensive because it shelled out to `git cat-file` for each formula that had been touched in the commit window.

Fixes Homebrew#13224
boblail added a commit to boblail/brew that referenced this issue May 4, 2022
`brew update` fast-forwards each tap from one commit to another. `update-report` lists all the formulae that were modified in that commit range. The clause this commit removes was filtering out modified formulae _whose `pkg_version` had not changed._

The outcome of this filtering:

- If you rewind homebrew/core **2,000 commits** (or 2 weeks), **819** formulae were modified. This clause would have taken **29.0 seconds** to filter out **153** (18.7%) of them.

- If you rewind homebrew/core **20,000 commits** (or 5 months), 3532 formulae were modified. This clause would have taken **119.4 seconds** to filter out **1121** (31.7%) of them.

Data
=========
| Homebrew Branch | Command | Commits Rewound | Time Elapsed | Updated Formulae |
| --- | --- | --- | --- | --- |
| `master` | `git -C "$(brew --repo homebrew/core)" reset --hard aa1b3d5; time sh -c "brew update &> output-2k.txt"` | 2,000 | 35.6s | 666 |
| `master` | `git -C "$(brew --repo homebrew/core)" reset --hard 11e6919; time sh -c "brew update &> output-20k.txt"` | 20,000 | 129.8s | 2411 |
| _this one_ | `git -C "$(brew --repo homebrew/core)" reset --hard aa1b3d5; time sh -c "brew update &> output-2k.txt"` | 2,000 | 6.6s | 819 |
| _this one_ | `git -C "$(brew --repo homebrew/core)" reset --hard 11e6919; time sh -c "brew update &> output-20k.txt"` | 20,000 | 10.4s | 3532 |

Root Cause
=========
This operation was so expensive because it shelled out to `git cat-file` for each formula that had been touched in the commit window.

Fixes Homebrew#13224
boblail added a commit to boblail/brew that referenced this issue May 4, 2022
| Homebrew Branch | Command | Commits Rewound | Time Elapsed | Updated Formulae |
| --- | --- | --- | --- | --- |
| `master` | `git -C "$(brew --repo homebrew/core)" reset --hard aa1b3d5; time sh -c "brew update &> output-2k.txt"` | 2,000 | 35.6s | 666 |
| `master` | `git -C "$(brew --repo homebrew/core)" reset --hard 11e6919; time sh -c "brew update &> output-20k.txt"` | 20,000 | 129.8s | 2411 |
| Homebrew#13234 | `git -C "$(brew --repo homebrew/core)" reset --hard aa1b3d5; time sh -c "brew update &> output-2k-unfiltered.txt"` | 2,000 | 6.6s | 819 |
| Homebrew#13234 | `git -C "$(brew --repo homebrew/core)" reset --hard 11e6919; time sh -c "brew update &> output-20k-unfiltered.txt"` | 20,000 | 10.4s | 3532 |
| _this one_ | `git -C "$(brew --repo homebrew/core)" reset --hard aa1b3d5; time sh -c "brew update &> output-2k-optimized.txt"` | 2,000 | 7.1s | 657† |
| _this one_ | `git -C "$(brew --repo homebrew/core)" reset --hard 11e6919; time sh -c "brew update &> output-20k-optimized.txt"` | 20,000 | 17.6s | 2411 |

† I haven't determined why there's a discrepancy between "Updated Formulae" on row 5 and row 1.

Fixes Homebrew#13224
boblail added a commit to boblail/brew that referenced this issue May 4, 2022
| Homebrew Branch | Command | Commits Rewound | Time Elapsed | Updated Formulae |
| --- | --- | --- | --- | --- |
| `master` | `git -C "$(brew --repo homebrew/core)" reset --hard aa1b3d5; time sh -c "brew update &> output-2k.txt"` | 2,000 | 35.6s | 666 |
| `master` | `git -C "$(brew --repo homebrew/core)" reset --hard 11e6919; time sh -c "brew update &> output-20k.txt"` | 20,000 | 129.8s | 2411 |
| Homebrew#13234 | `git -C "$(brew --repo homebrew/core)" reset --hard aa1b3d5; time sh -c "brew update &> output-2k-unfiltered.txt"` | 2,000 | 6.6s | 819 |
| Homebrew#13234 | `git -C "$(brew --repo homebrew/core)" reset --hard 11e6919; time sh -c "brew update &> output-20k-unfiltered.txt"` | 20,000 | 10.4s | 3532 |
| _this one_ | `git -C "$(brew --repo homebrew/core)" reset --hard aa1b3d5; time sh -c "brew update &> output-2k-optimized.txt"` | 2,000 | 7.1s | 657† |
| _this one_ | `git -C "$(brew --repo homebrew/core)" reset --hard 11e6919; time sh -c "brew update &> output-20k-optimized.txt"` | 20,000 | 17.6s | 2411 |

† I haven't determined why there's a discrepancy between "Updated Formulae" on row 5 and row 1.

Fixes Homebrew#13224
boblail added a commit to boblail/brew that referenced this issue May 4, 2022
| Homebrew Branch | Command | Commits Rewound | Time Elapsed | Updated Formulae |
| --- | --- | --- | --- | --- |
| `master` | `git -C "$(brew --repo homebrew/core)" reset --hard aa1b3d5; time sh -c "brew update &> output-2k.txt"` | 2,000 | 35.6s | 666 |
| `master` | `git -C "$(brew --repo homebrew/core)" reset --hard 11e6919; time sh -c "brew update &> output-20k.txt"` | 20,000 | 129.8s | 2411 |
| Homebrew#13234 | `git -C "$(brew --repo homebrew/core)" reset --hard aa1b3d5; time sh -c "brew update &> output-2k-unfiltered.txt"` | 2,000 | 6.6s | 819 |
| Homebrew#13234 | `git -C "$(brew --repo homebrew/core)" reset --hard 11e6919; time sh -c "brew update &> output-20k-unfiltered.txt"` | 20,000 | 10.4s | 3532 |
| _this one_ | `git -C "$(brew --repo homebrew/core)" reset --hard aa1b3d5; time sh -c "brew update &> output-2k-optimized.txt"` | 2,000 | 7.1s | 657† |
| _this one_ | `git -C "$(brew --repo homebrew/core)" reset --hard 11e6919; time sh -c "brew update &> output-20k-optimized.txt"` | 20,000 | 17.6s | 2411 |

† I haven't determined why there's a discrepancy between "Updated Formulae" on row 5 and row 1.

Fixes Homebrew#13224
boblail added a commit to boblail/brew that referenced this issue May 4, 2022
| Homebrew Branch | Command | Commits Rewound | Time Elapsed | Updated Formulae |
| --- | --- | --- | --- | --- |
| `master` | `git -C "$(brew --repo homebrew/core)" reset --hard aa1b3d5; time sh -c "brew update &> output-2k.txt"` | 2,000 | 35.6s | 666 |
| `master` | `git -C "$(brew --repo homebrew/core)" reset --hard 11e6919; time sh -c "brew update &> output-20k.txt"` | 20,000 | 129.8s | 2411 |
| Homebrew#13234 | `git -C "$(brew --repo homebrew/core)" reset --hard aa1b3d5; time sh -c "brew update &> output-2k-unfiltered.txt"` | 2,000 | 6.6s | 819 |
| Homebrew#13234 | `git -C "$(brew --repo homebrew/core)" reset --hard 11e6919; time sh -c "brew update &> output-20k-unfiltered.txt"` | 20,000 | 10.4s | 3532 |
| _this one_ | `git -C "$(brew --repo homebrew/core)" reset --hard aa1b3d5; time sh -c "brew update &> output-2k-optimized.txt"` | 2,000 | 7.1s | 657† |
| _this one_ | `git -C "$(brew --repo homebrew/core)" reset --hard 11e6919; time sh -c "brew update &> output-20k-optimized.txt"` | 20,000 | 17.6s | 2411 |

† I haven't determined why there's a discrepancy between "Updated Formulae" on row 5 and row 1.

Fixes Homebrew#13224
@boblail
Copy link
Contributor Author

boblail commented Jun 13, 2022

I think this is resolved by #13299 and #13375

@boblail boblail closed this as completed Jun 13, 2022
@github-actions github-actions bot added the outdated PR was locked due to age label Jul 14, 2022
@github-actions github-actions bot locked as resolved and limited conversation to collaborators Jul 14, 2022
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Labels
bug Reproducible Homebrew/brew bug help wanted We want help addressing this outdated PR was locked due to age
Projects
None yet
2 participants