base: performance: operations slower in 2.7.x vs. 2.6.4: reclaim, clean

[mascguy (Christopher Nielsen)]

I've noticed that the two operations mentioned - reclaim and clean - are noticeably slower with MacPorts 2.7.x vs. 2.6.4.

Per some discussion with Josh, we believe there haven't been any notable changes to these operations for the 2.7.x releases, so they should perform similarly to v2.6.4.

The standard disclaimer applies: As I'm running on an ancient 2008-era MacPro, I'm far more likely to notice things like this vs. 99% of our users. Nonetheless, if there is a performance regression - and it can be identified and resolved - it will be to everyone's benefit.

In terms of the approach: We'll enable TCL profiling, and generate results for each of the operations (reclaim and clean), across both v2.6.4 and v2.7.1. To ensure we're comparing apples-to-apples, that will be done via a cloned VM, with an identical set of installed ports. The operations will also be run twice, with the first run done to prime the filesystem cache. The 2nd run will include profiling enabled.

This should be very straightforward: It's simply a matter of generating results, upgrading MacPorts, and repeating the process. Once done, I'll attach the various profiler outputs for analysis.

Thoughts/comments welcome, as always.

[mascguy (Christopher Nielsen)]

Details for operation reclaim: The check for unused distfiles is the key area where I've noticed the most slowdown. And interestingly enough, immediately running a 2nd iteration - with a potential benefit from a primed filesystem cache - doesn't yield much of an improvement. So something is coming into play.

[mascguy (Christopher Nielsen)]

While I'm still working on generating profiler results, the following timings illustrate the problem. These were run in a macOS 10.12 VM, though the specific macOS release doesn't matter; they're consistent across versions.

Operation	Time: 2.6.4	Time: 2.7.1
port reclaim	25.4 secs	50.2 secs
port clean --all installed	28.7 secs	54.1 secs

Interestingly enough, the processing time is nearly doubled for 2.7.x, vs. 2.6.4.

Is it possible we made a change - inadvertent or otherwise - which results in the various logic running twice for each operation?

That doesn't appear to be the case based on debug-level logging, and seems a bit far-fetched. But it would certainly explain the doubling in total processing time.