Opened 3 years ago

Closed 2 years ago

Last modified 17 months ago

#63068 closed defect (fixed)

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

Reported by: mascguy (Christopher Nielsen) Owned by: mascguy (Christopher Nielsen)
Priority: Normal Milestone:
Component: base Version: 2.7.1
Keywords: Cc: jmroot (Joshua Root), l2dy (Zero King)
Port:

Description (last modified by 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.

Attachments (8)

port-profile-reclaim-mp-2.6.x.txt (636.9 KB) - added by mascguy (Christopher Nielsen) 3 years ago.
port-profile-reclaim-mp-2.7.x.txt (644.9 KB) - added by mascguy (Christopher Nielsen) 3 years ago.
port-profile-clean-mp-2.6.x.txt (147.3 KB) - added by mascguy (Christopher Nielsen) 3 years ago.
port-profile-clean-mp-2.7.x.txt (147.6 KB) - added by mascguy (Christopher Nielsen) 3 years ago.
port-procprofile-clean-mp-2.6.x.txt (25.5 KB) - added by mascguy (Christopher Nielsen) 3 years ago.
port-procprofile-clean-mp-2.7.x.txt (25.6 KB) - added by mascguy (Christopher Nielsen) 3 years ago.
port-procprofile-reclaim-mp-2.6.x.txt (24.0 KB) - added by mascguy (Christopher Nielsen) 3 years ago.
port-procprofile-reclaim-mp-2.7.x.txt (24.2 KB) - added by mascguy (Christopher Nielsen) 3 years ago.

Download all attachments as: .zip

Change History (25)

comment:1 Changed 3 years ago by mascguy (Christopher Nielsen)

Component: portsbase

comment:2 Changed 3 years ago by 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.

comment:3 Changed 3 years ago by 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.

Last edited 3 years ago by mascguy (Christopher Nielsen) (previous) (diff)

comment:4 Changed 3 years ago by mascguy (Christopher Nielsen)

Description: modified (diff)
Summary: base: performance: operations slower in 2.7.x vs. 2.6.4: reclaim, rev-upgrade, cleanbase: performance: operations slower in 2.7.x vs. 2.6.4: reclaim, clean

comment:5 Changed 3 years ago by mascguy (Christopher Nielsen)

Description: modified (diff)

Changed 3 years ago by mascguy (Christopher Nielsen)

Changed 3 years ago by mascguy (Christopher Nielsen)

comment:6 Changed 3 years ago by 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

Changed 3 years ago by mascguy (Christopher Nielsen)

Changed 3 years ago by mascguy (Christopher Nielsen)

comment:7 Changed 3 years ago by 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

comment:8 Changed 3 years ago by 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]

Changed 3 years ago by mascguy (Christopher Nielsen)

Changed 3 years ago by mascguy (Christopher Nielsen)

Changed 3 years ago by mascguy (Christopher Nielsen)

Changed 3 years ago by mascguy (Christopher Nielsen)

comment:9 Changed 3 years ago by 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

comment:10 Changed 3 years ago by 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.

comment:11 Changed 3 years ago by 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.

comment:12 in reply to:  11 Changed 3 years ago by 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.

Last edited 3 years ago by mascguy (Christopher Nielsen) (previous) (diff)

comment:13 Changed 3 years ago by 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.

comment:14 Changed 3 years ago by l2dy (Zero King)

Cc: l2dy added

comment:15 Changed 2 years ago by mascguy (Christopher Nielsen)

Resolution: fixed
Status: assignedclosed

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.

comment:16 Changed 2 years ago by 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.

comment:17 in reply to:  16 Changed 17 months ago by 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!

Note: See TracTickets for help on using tickets.