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.

[mascguy (Christopher Nielsen)]

Attached profiler output for port reclaim; filenames:

• port-profile-reclaim-mp-2.6.x.txt
• port-profile-reclaim-mp-2.7.x.txt

[mascguy (Christopher Nielsen)]

Attached profiler output for port clean --all installed; filenames:

• port-profile-clean-mp-2.6.x.txt
• port-profile-clean-mp-2.7.x.txt

[mascguy (Christopher Nielsen)]

Re-profiled both operations, to obtain proc-based timings.

Switched to the following TCL wrapper, to avoid having to modify MacPorts itself:

#!/opt/local/libexec/macports/bin/tclsh8.5

package require profiler

proc ::exit {} {
    puts stderr "Exit call intercepted"
}

puts stderr "Profiler - Init"
::profiler::init

if {[catch { [source /opt/local/bin/port] } result_or_errormsg]} {
    #handle error
} else {
    #normal processing
}

puts stderr "Profiler - Done"
puts stderr [::profiler::sortFunctions exclusiveRuntime]

[mascguy (Christopher Nielsen)]

Proc-based timing results attached; filenames:

• port-procprofile-reclaim-mp-2.6.x.txt
• port-procprofile-reclaim-mp-2.7.x.txt
• port-procprofile-clean-mp-2.6.x.txt
• port-procprofile-clean-mp-2.7.x.txt

[mascguy (Christopher Nielsen)]

Josh, I'm done at this point, unless any profiling refinements are needed.

When you get a chance, take a look at the profiler results, and let me know your thoughts.

[jmroot (Joshua Root)]

It looks like the main difference is likely something running in the portfile interpreter, so that's where you would need to profile, like in #56793.

[mascguy (Christopher Nielsen)]

Replying to jmroot:

It looks like the main difference is likely something running in the portfile interpreter, so that's where you would need to profile, like in #56793.

Makes sense, I'll try to re-profile over the coming days.

[mascguy (Christopher Nielsen)]

Wow, can't believe it's been seven weeks since last working on this. I'll add this to top of my work backlog, to ensure it doesn't languish.

[mascguy (Christopher Nielsen)]

Given the various fixes and improvements in 2.7.x - along with further pending changes for 2.8.x - we're in good shape. Closing as fixed.

[jmroot (Joshua Root)]

Are you seeing better port clean performance? I know reclaim was improved, though not by undoing any change that 2.7 made.

[mascguy (Christopher Nielsen)]

Replying to jmroot:

Are you seeing better port clean performance? I know reclaim was improved, though not by undoing any change that 2.7 made.

My primary Mac is slightly faster now - upgraded to a MacPro 2012 last year, vs. a 2008 previously - and the latter is currently out-of-commission. (Need to purchase another AMD Metal-compatible GPU, as the current one moved into the 2012.)

But a better test platform might be my old 2006-era MacBookPro. So at some point I'll install 2.64 in a separate prefix, run some timing tests, and compare to our latest 2.8.x release. Stay tuned!