Tests in test/unit/ take way too long

[rileyjmurray]

I work with a Macbook Pro with a 12-core M2 Pro CPU. If I install pytest-xdist (to enable parallel tests) and then run pytest -n auto test/unit --durations=20, I get the following. There's an insane amount of time spent on the 10 or so slowest tests.

=================================================================================================== slowest 20 durations ====================================================================================================
1592.01s call     test/unit/tools/test_errgenproptools.py::ErrgenCompositionCommutationTester::test_errorgen_composition
1505.58s call     test/unit/tools/test_errgenproptools.py::ApproxStabilizerMethodTester::test_alpha
467.73s call     test/unit/protocols/test_rb.py::TestCliffordRBDesign::test_parallel_design_construction
391.56s call     test/unit/objects/test_circuit.py::CircuitMethodTester::test_convert_to_cirq
275.94s call     test/unit/objects/test_forwardsim.py::ForwardSimConsistencyTester::test_consistent_jacs
267.55s call     test/unit/tools/test_errgenproptools.py::ApproxStabilizerMethodTester::test_stabilizer_probability_correction
263.35s call     test/unit/tools/test_errgenproptools.py::ApproxStabilizerMethodTester::test_approximate_stabilizer_probabilities
203.66s call     test/unit/tools/test_errgenproptools.py::ApproxStabilizerMethodTester::test_phi
167.68s call     test/unit/tools/test_errgenproptools.py::ApproxStabilizerMethodTester::test_approximate_stabilizer_probability
148.52s call     test/unit/tools/test_edesigntools.py::FisherInformationTester::test_calculate_fisher_information_matrix_with_instrument
117.19s call     test/unit/tools/test_errgenproptools.py::ErrgenCompositionCommutationTester::test_bch_approximation
87.17s call     test/unit/modelmembers/test_operation.py::StaticOpTester::test_diamonddist
86.65s call     test/unit/modelmembers/test_operation.py::LinearlyParamOpTester::test_diamonddist
82.30s call     test/unit/modelmembers/test_operation.py::DiagonalCPTPLindbladDenseOpTester::test_diamonddist
79.26s call     test/unit/modelmembers/test_operation.py::AffineShiftOpTester::test_diamonddist
78.29s call     test/unit/modelmembers/test_operation.py::FullOpTester::test_diamonddist
73.89s call     test/unit/tools/test_errgenproptools.py::ApproxStabilizerMethodTester::test_approximate_stabilizer_pauli_expectation
58.17s call     test/unit/report/test_colormaps.py::BasicColormapTester::test_get_matplotlib_norm_and_cmap
58.16s call     test/unit/report/test_colormaps.py::PiecewiseLinearColormapTester::test_get_matplotlib_norm_and_cmap
56.92s call     test/unit/protocols/test_rb.py::TestInterleavedRBProtocol::test_interleavedrb_protocol_noisy

I suggest extremely expensive unit tests be moved into a different folder. Thoughts, @coreyostrove ?

[coreyostrove]

Yeah, I noticed this behavior a while back while puzzling over github logs. What version of python are you using? (See below for relevance of that question). Most of these stragglers are tests that I added with the introduction of the error generator propagation test. Some of the tests in the logs you shared could be safely moved into 'test_packages' and only get run against beta/master. My preference would be to keep the error generator propagation tests in unit since there is still a lot of active development going on which touches this part of the code, and having issues flagged early is still advantageous. The time being taken is a problem though, and there are two things going on here:

1. There is a massive performance difference between runners on different versions of python. This recent log from one of Juan's branches is emblematic of this. The ubuntu runners on python 3.9 took about 36 minutes (which is in the ballpark of what the test suite takes on my windows machine on 3.9), but on 3.12 takes over 4 hours (over 6 times longer). There's clearly a performance regression somewhere, but I haven't had a chance to track this down, and if we can identify this and patch it this would go a long way to fixing this issue (and will be independently valuable to users of the error generator propagation code).
2. The error generator propagation tests taking the longest are pretty overcomplete, and we should be able to significantly reduce the number of cases they're testing. The error generator composition tests, for example, could probably safely get away with checking just one representative test case for each commutation relation class, rather than testing every possible composition as is currently being done.

[rileyjmurray]

Tests run for PR #622 failed on Windows, Python 3.12, because they hit the 6 hour time limit.

https://github.com/sandialabs/pyGSTi/actions/runs/16636571421/job/47078557972?pr=622

[rileyjmurray]

PR #624 merged in duration logging for our continuous integration tests. See below for summary times from Windows and Ubuntu with Python 3.9 and 3.12.

TL;DR: ErrgenCompositionCommutationTester is doing the most damage.

• Ubuntu: 850 seconds for Python 3.9, and 13000 seconds for Python 3.12.
• Windows 650 seconds for Python 3.9 and 8400 seconds for Python 3.12.

Ubuntu

============================== ubuntu, python 3.9 ==============================
============================= slowest 25 durations =============================
844.58s call     test/unit/tools/test_errgenproptools.py::ErrgenCompositionCommutationTester::test_errorgen_composition
414.00s call     test/unit/tools/test_edesigntools.py::FisherInformationTester::test_calculate_fisher_information_matrix_with_instrument
205.10s call     test/unit/tools/test_errgenproptools.py::ApproxStabilizerMethodTester::test_alpha
149.88s call     test/unit/protocols/test_rb.py::TestInterleavedRBProtocol::test_interleavedrb_protocol_noisy
125.02s call     test/unit/tools/test_errgenproptools.py::ApproxStabilizerMethodTester::test_approximate_stabilizer_pauli_expectation
 94.89s call     test/unit/protocols/test_rb.py::TestInterleavedRBProtocol::test_interleavedrb_protocol_ideal
 48.22s call     test/unit/objects/test_errorgenpropagation.py::ErrorgenPropTester::test_explicit_model
 44.37s call     test/unit/tools/test_errgenproptools.py::ApproxStabilizerMethodTester::test_approximate_stabilizer_probability
 43.08s call     test/unit/tools/test_errgenproptools.py::ApproxStabilizerMethodTester::test_stabilizer_probability_correction
 37.15s call     test/unit/tools/test_errgenproptools.py::ApproxStabilizerMethodTester::test_stabilizer_pauli_expectation_correction
 33.13s call     test/unit/drivers/test_longsequence.py::HPlusSGatesTester::test_long_sequence_gst
 31.25s setup    test/unit/protocols/test_protocols.py::ExperimentDesignTester::test_add_to_combined_design
 28.47s call     test/unit/tools/test_errgenproptools.py::ApproxStabilizerMethodTester::test_approximate_stabilizer_probabilities
 26.66s call     test/unit/tools/test_errgenproptools.py::ApproxStabilizerMethodTester::test_alpha_pauli
 23.43s call     test/unit/algorithms/test_gaugeopt.py::LGSTGaugeOptAutoMethodTester::test_gaugeopt_spam_metrics
 19.46s call     test/unit/tools/test_errgenproptools.py::ErrgenCompositionCommutationTester::test_iterative_error_generator_composition
 17.92s call     test/unit/tools/test_errgenproptools.py::ApproxStabilizerMethodTester::test_phi
 16.39s call     test/unit/drivers/test_longsequence.py::StdPracticeGSTTester::test_stdpractice_gst_CPTP
 16.38s call     test/unit/objects/test_forwardsim.py::ForwardSimIntegrationTester::test_simple_matrix_fwdsim
 15.53s call     test/unit/objects/test_forwardsim.py::ForwardSimIntegrationTester::test_simple_map_fwdsim
 15.12s call     test/unit/tools/test_symplectic.py::SymplecticOddDimTester::test_fast_compose_cliffords
 13.27s call     test/unit/drivers/test_longsequence.py::CPTPGatesTester::test_long_sequence_gst
 12.69s call     test/unit/algorithms/test_gaugeopt.py::LGSTGaugeOptSPAMPenaltyTester::test_gaugeopt_no_target
 11.89s call     test/unit/tools/test_errgenproptools.py::ErrgenCompositionCommutationTester::test_errorgen_commutators
 11.57s call     test/unit/protocols/test_rb.py::TestInterleavedRBDesign::test_serialization
========= 1947 passed, 64 skipped, 8112 warnings in 1762.74s (0:29:22) =========

============================== ubuntu, python 3.12 =============================
============================= slowest 25 durations =============================
13004.70s call     test/unit/tools/test_errgenproptools.py::ErrgenCompositionCommutationTester::test_errorgen_composition
401.57s call     test/unit/tools/test_edesigntools.py::FisherInformationTester::test_calculate_fisher_information_matrix_with_instrument
305.61s call     test/unit/tools/test_errgenproptools.py::ErrgenCompositionCommutationTester::test_iterative_error_generator_composition
223.81s call     test/unit/tools/test_errgenproptools.py::ApproxStabilizerMethodTester::test_alpha
 88.77s call     test/unit/protocols/test_rb.py::TestInterleavedRBProtocol::test_interleavedrb_protocol_noisy
 84.37s call     test/unit/tools/test_errgenproptools.py::ApproxStabilizerMethodTester::test_approximate_stabilizer_pauli_expectation
 81.72s call     test/unit/protocols/test_rb.py::TestInterleavedRBProtocol::test_interleavedrb_protocol_ideal
 47.53s call     test/unit/objects/test_errorgenpropagation.py::ErrorgenPropTester::test_explicit_model
 38.69s call     test/unit/tools/test_errgenproptools.py::ApproxStabilizerMethodTester::test_approximate_stabilizer_probability
 35.86s call     test/unit/tools/test_errgenproptools.py::ApproxStabilizerMethodTester::test_stabilizer_probability_correction
 30.44s call     test/unit/tools/test_errgenproptools.py::ApproxStabilizerMethodTester::test_stabilizer_pauli_expectation_correction
 26.61s setup    test/unit/protocols/test_protocols.py::ExperimentDesignTester::test_add_to_combined_design
 18.78s call     test/unit/algorithms/test_gaugeopt.py::LGSTGaugeOptAutoMethodTester::test_gaugeopt_spam_metrics
 17.39s call     test/unit/tools/test_errgenproptools.py::ApproxStabilizerMethodTester::test_phi
 17.34s call     test/unit/tools/test_errgenproptools.py::ApproxStabilizerMethodTester::test_approximate_stabilizer_probabilities
 16.22s call     test/unit/tools/test_errgenproptools.py::ApproxStabilizerMethodTester::test_alpha_pauli
 15.31s call     test/unit/objects/test_forwardsim.py::ForwardSimIntegrationTester::test_simple_map_fwdsim
 15.27s call     test/unit/objects/test_forwardsim.py::ForwardSimIntegrationTester::test_simple_matrix_fwdsim
 14.57s call     test/unit/drivers/test_longsequence.py::StdPracticeGSTTester::test_stdpractice_gst_CPTP
 14.51s call     test/unit/tools/test_symplectic.py::SymplecticOddDimTester::test_fast_compose_cliffords
 10.74s call     test/unit/construction/test_modelconstruction.py::ModelConstructionTester::test_instruments_in_processorspecs
 10.40s call     test/unit/protocols/test_rb.py::TestInterleavedRBDesign::test_serialization
 10.40s call     test/unit/tools/test_errgenproptools.py::ErrgenCompositionCommutationTester::test_errorgen_commutators
 10.34s call     test/unit/protocols/test_rb.py::TestCliffordRBProtocol::test_cliffordrb_protocol_ideal
 10.22s call     test/unit/protocols/test_rb.py::TestInterleavedRBDesign::test_combined_design_access
======== 1947 passed, 64 skipped, 8135 warnings in 14159.34s (3:55:59) =========

Windows

============================= windows, python 3.9 =============================
============================ slowest 25 durations =============================
648.60s call     test/unit/tools/test_errgenproptools.py::ErrgenCompositionCommutationTester::test_errorgen_composition
644.61s call     test/unit/objects/test_errorgenpropagation.py::ErrorgenPropTester::test_explicit_model
429.27s call     test/unit/tools/test_edesigntools.py::FisherInformationTester::test_calculate_fisher_information_matrix_with_instrument
250.29s call     test/unit/drivers/test_longsequence.py::HPlusSGatesTester::test_long_sequence_gst
224.60s call     test/unit/drivers/test_longsequence.py::CPTPGatesTester::test_long_sequence_gst
174.81s call     test/unit/drivers/test_longsequence.py::StdPracticeGSTTester::test_stdpractice_gst_CPTP
170.82s call     test/unit/tools/test_errgenproptools.py::ApproxStabilizerMethodTester::test_approximate_stabilizer_pauli_expectation
167.60s call     test/unit/protocols/test_rb.py::TestInterleavedRBProtocol::test_interleavedrb_protocol_ideal
156.95s call     test/unit/protocols/test_rb.py::TestInterleavedRBProtocol::test_interleavedrb_protocol_noisy
138.59s call     test/unit/drivers/test_longsequence.py::SGatesTester::test_long_sequence_gst
136.98s call     test/unit/objects/test_model.py::LindbladModelTester::test_bulk_fill_hprobs
133.95s call     test/unit/drivers/test_longsequence.py::GLNDModelTester::test_long_sequence_gst
132.93s call     test/unit/protocols/test_rb.py::TestMirrorRBDesign::test_clifford_design_construction
131.87s call     test/unit/tools/test_errgenproptools.py::ApproxStabilizerMethodTester::test_alpha
122.91s call     test/unit/modelmembers/test_operation.py::StaticStdOpTester::test_densitymx_svterm_cterm
115.91s call     test/unit/protocols/test_rb.py::TestMirrorRBProtocol::test_mirrorrb_protocol_noisy
 96.79s call     test/unit/tools/test_errgenproptools.py::ApproxStabilizerMethodTester::test_approximate_stabilizer_probability 
 96.77s call     test/unit/modelmembers/test_operation.py::StaticStdOpTester::test_statevec
 96.18s call     test/unit/tools/test_errgenproptools.py::ApproxStabilizerMethodTester::test_stabilizer_probability_correction
 87.20s call     test/unit/tools/test_errgenproptools.py::ApproxStabilizerMethodTester::test_stabilizer_pauli_expectation_correction
 78.73s call     test/unit/protocols/test_rb.py::TestMirrorRBProtocol::test_mirrorrb_protocol_ideal
 77.42s setup    test/unit/protocols/test_protocols.py::ExperimentDesignTester::test_add_to_combined_design
 74.92s call     test/unit/objects/test_model.py::StaticModelTester::test_set_all_parameterizations_HS
 74.79s call     test/unit/protocols/test_rb.py::TestMirrorRBDesign::test_design_construction
 72.75s call     test/unit/objects/test_model.py::StaticModelTester::test_parameter_bounds
======== 1947 passed, 64 skipped, 8112 warnings in 3998.49s (1:06:38) =========

============================= windows, python 3.12 ============================
============================ slowest 25 durations =============================
8409.59s call     test/unit/tools/test_errgenproptools.py::ErrgenCompositionCommutationTester::test_errorgen_composition
423.37s call     test/unit/tools/test_edesigntools.py::FisherInformationTester::test_calculate_fisher_information_matrix_with_instrument
265.22s call     test/unit/tools/test_errgenproptools.py::ErrgenCompositionCommutationTester::test_iterative_error_generator_composition
116.04s call     test/unit/tools/test_errgenproptools.py::ApproxStabilizerMethodTester::test_approximate_stabilizer_pauli_expectation
 97.73s call     test/unit/tools/test_errgenproptools.py::ApproxStabilizerMethodTester::test_alpha
 83.72s call     test/unit/protocols/test_rb.py::TestInterleavedRBProtocol::test_interleavedrb_protocol_ideal
 79.66s call     test/unit/protocols/test_rb.py::TestInterleavedRBProtocol::test_interleavedrb_protocol_noisy
 47.09s call     test/unit/tools/test_errgenproptools.py::ApproxStabilizerMethodTester::test_approximate_stabilizer_probability
 46.37s call     test/unit/tools/test_errgenproptools.py::ApproxStabilizerMethodTester::test_stabilizer_probability_correction
 39.36s call     test/unit/tools/test_errgenproptools.py::ApproxStabilizerMethodTester::test_stabilizer_pauli_expectation_correction
 32.99s call     test/unit/mpi/test_mpi.py::MPITester::test_all
 32.23s call     test/unit/protocols/test_rb.py::TestCliffordRBDesign::test_parallel_design_construction
 25.93s call     test/unit/protocols/test_rb.py::TestDirectRBDesign::test_design_construction
 25.26s call     test/unit/protocols/test_rb.py::TestMirrorRBDesign::test_design_construction
 19.57s call     test/unit/objects/test_errorgenpropagation.py::ErrorgenPropTester::test_explicit_model
 18.16s call     test/unit/tools/test_errgenproptools.py::ApproxStabilizerMethodTester::test_phi
 17.10s call     test/unit/tools/test_errgenproptools.py::ApproxStabilizerMethodTester::test_approximate_stabilizer_probabilities
 16.69s call     test/unit/objects/test_forwardsim.py::ForwardSimIntegrationTester::test_simple_matrix_fwdsim
 16.19s call     test/unit/tools/test_errgenproptools.py::ApproxStabilizerMethodTester::test_alpha_pauli
 16.17s call     test/unit/objects/test_forwardsim.py::ForwardSimIntegrationTester::test_simple_map_fwdsim
 13.80s setup    test/unit/protocols/test_protocols.py::ExperimentDesignTester::test_add_to_combined_design
 13.79s call     test/unit/tools/test_errgenproptools.py::ErrgenCompositionCommutationTester::test_errorgen_commutators
 12.13s call     test/unit/algorithms/test_gaugeopt.py::LGSTGaugeOptAutoMethodTester::test_gaugeopt_spam_metrics
 11.45s call     test/unit/modelmembers/test_kraus_interface.py::KrausInterfaceStateVecSlowTester::test_depol_model_histogram
 10.22s call     test/unit/modelmembers/test_kraus_interface.py::KrausInterfaceStateVecTester::test_depol_model_histogram
======== 1947 passed, 64 skipped, 8111 warnings in 9423.66s (2:37:03) =========

Raw logs

develop-test-durations-ubuntu-3.9.txt
develop-test-durations-ubuntu-3.12.txt
develop-test-durations-windows-3.9.txt
develop-test-durations-windows-3.12.txt

[rileyjmurray]

I ran cprofile for test_errgenproptools.py in Python 3.11 and 3.12 on my M2 Pro machine. The command was essentially

python -m cProfile -o tools/cprof_test_errgen_optools.prof tools/test_errgenproptools.py

where I modified tools/test_errgenproptools.py so it ended with pytest.main([__file__]) to launch the tests

I saw very little runtime variation between Python 3.11 and 3.12. I'll go and try Python 3.9, and maybe revisit the runs of 3.11 and 3.12 to make sure they have what I want them to have. In any case, here are the top lines of the snakeviz report. Both runs show over 200 seconds on over 300,000 calls to pauli_phase_update (which is an almost pure-python function with modest use of for loops).

Python 3.11.

Python 3.12.

[coreyostrove]

Thanks for this profiling, @rileyjmurray! I look forward to seeing the profiling for python 3.9 so we can track down where these diverge. For what its worth, in parallel to this I just published a branch, egprop-unit-test-durations where I have streamlined the main offending tests to reduce the number of test cases. I still want to know where there 13X performance regression is coming from, though, so thanks for helping figure this out!

[coreyostrove]

I spent a bit of time yesterday trying to reproduce this performance difference locally (windows 11, intel xeon processor) by running these tests (more specifically the composition test, which is the main offender) on both python 3.9 and python 3.12, but have not been able to reliably reproduce the very large discrepancies being seen here on the runners (and your machine, @rileyjmurray). Since you have been able to reproduce some of this behavior, @rileyjmurray, I'm going to lean on your profiling to see if we can figure this out.

In the meantime, the very long unit test times are starting to bottleneck progress on the next release, so I'm going to merge in the changes I alluded to on egprop-unit-test-durations and at least band-aid this for now, with the intention of taking another crack at properly fixing this when we get some additional data.

[coreyostrove]

Quick update, I folded the unit test changes I alluded to into PR #625. Runtime on python 3.12 with the streamlined tests is down to about 30 minutes. Still want to figure out the underlying issue, but 30 minutes is definitely a lot less painful...