Profiling is done, and the answer is very simple: all of the time is going into S3 existence checks inside Datastore.ingest.  That's good news, because I bet that's something we can fix with a relatively small patch that could be backported to the v23 branch.  I'll take a look at that next.  Aside from the fact that we don't need to do existence checks here at all, it looks from the profile like we might be doing them all twice: once in _prepIngest / _standardizeIngestPath, and once in _finishIngest / _extractIngestInfo. Tim Jenness, feel free to ping me on Slack today (despite it being Friday) if you want to weigh in on how to approach this.

I've attached the profile as slow-eb.profile.

As an aside, I also took the opportunity to profile QG generation for this step (it took 30 minutes, which is ok only from the perspective that it's in the "expected" range due to known issues).  But it turns out the database queries (what those known issues involve) are only 24% (7min), and the rest looks a lot like it's basically the kind of Python logic we could only speed up by moving things to a compiled language.  I think it might be time to start thinking seriously about how we might approach that; I think the scope of what we'd want to move to a compiled extension module is basically everything in a QuantumGraph, which means DatasetRef, some kind of container of DatasetRef and everything that goes into that.  The QG generation profile is also attached as slow-eb-qg.profile.

I imagine execution butler creation needs to be able to pass a flag to ingest to say "trust me, I know these files really do exist". I can take a look.

I'll also see if the ingest code can pass around a cache of previous checks – it's also possible that the existence checks can be parallelized, which is something I did for transfer-datasets when the merge job was slow (and that really does currently need to check for file existence)

Ok, I've reassigned to you since you're looking into making code changes, and what I've done didn't take much time. Send it back if you'd like.

Okay. A few things:

• There is a new switch to ingest() that indicates not to bother recording the file size. That would remove 38% of the overhead.
• The problem though is that the execution butler is build using export + import. It is not built as a butler to butler transfer. This means that there is no mechanism in place to pass that parameter in to the datastore ingest.
• If Butler.transfer_from() was used then some of the inefficiencies would go away since it would be transferring datastore records over in bulk. Maybe I should take a look to see if using that API is relatively simple.

Here is a screen grab of a subset of the profile:

Here's my attempt to reconstruct them (I lost the RSP instance used to do this originally, and apparently shell history isn't saved).

First make the QG, since it's too painful to share those (takes about 45min, I think?  Or 30min if you don't run the profiler here.):

python -m cProfile -o slow-eb-qg.profile $CTRL_MPEXEC_DIR/bin/pipetask qgraph -b s3://butler-us-central1-panda-dev/dc2/butler-external.yaml -i 2.2i/defaults/DP0.2 -i 2.2i/runs/DP0.2/v23_0_0_rc5/PREOPS-905 --output-run u/jbosch/slow-eb -p $OBS_LSST_DIR/pipelines/imsim/DRP.yaml#step2 -q slow-eb.qgraph -d "instrument='LSSTCam-imSim' and skymap='DC2' and visit >=1472 and visit <= 206020"

then make the execution butler (ran overnight):

python -m cProfile -o slow-eb.profile $CTRL_MPEXEC_DIR/bin/pipetask qgraph -b s3://butler-us-central1-panda-dev/dc2/butler-external.yaml -i 2.2i/defaults/DP0.2 -i 2.2i/runs/DP0.2/v23_0_0_rc5/PREOPS-905 --output-run u/jbosch/slow-eb --save-execution-butler slow-eb.sqlite3 -g slow-eb.qgraph

Switching from export/import to Butler.transfer_from() the entire execution butler step takes about 20 minutes. It's a very small patch to enable this.

The profile now shows that 75% of the time is in execution butler creation and 23% in reading the graph. Of that 75%, half is doing the datastore transfer (but no file system checks) and quarter each for export and import.

I could probably do with a verbose log message in Butler.transfer_from for when it actually completes – at the moment you are told when all the refs have been imported into registry but not when the datastore transfer has completed.

Looks good!

For posterity, the conversation about the difference between old and new execution butlers happened on the PR: we're no longer saving TAGGED and CALIBRATION memberships, but we never had to.