[MRG] Improve DUL performance #651

mself · 2021-06-21T17:08:28Z

Reference issue

Issue #650

What changed

Instead of sleeping before every event in run_reactor(), only sleep when there are no queued events to process.

This ensures that queued events are processed as fast as possible. The _run_loop_delay setting now only affects the case where there are no queued events (i.e. the system is idle).

After the performance optimization, pynetdicom C-STORE SCU is ~23x faster than before when transferring large DICOMs, such as the 2MB RTImageStorage.dcm (0.87 sec vs 19.66 sec):

Benchmark BEFORE:

1) C-STORE SCU transferred 100 total RTImageStorage.dcm datasets over 1 association in 19.66 s
9) C-STORE SCU/SCP transferred 100 total RTImageStorage.dcm datasets over 1 association in 20.85 s
10) C-STORE DCMTK SCU/SCP transferred 100 total RTImageStorage.dcm datasets over 1 association in 0.20 s

Benchmark AFTER:

1) C-STORE SCU transferred 100 total RTImageStorage.dcm datasets over 1 association in 0.87 s
9) C-STORE SCU/SCP transferred 100 total RTImageStorage.dcm datasets over 1 association in 1.41 s
10) C-STORE DCMTK SCU/SCP transferred 100 total RTImageStorage.dcm datasets over 1 association in 0.22 s

Now pynetdicom C-STORE SCU is only ~4x slower than DCMTK (0.87 sec vs. 0.22 sec) instead of ~100x for RTImageStorage.dcm.

The improvement is much more modest for small DICOMs, such as the 39KB CTImageStorage.dcm (only ~2x speedup).

The ultrasound images we typically see in our use case are ~200MB and we saw a ~30x speedup on C-STORE SCU with this change.

How it was tested

All unit tests pass. Some unit tests had to be updated to avoid timing-dependent failures.

Also, one unit test fails on master even before the changes:

pynetdicom/apps/tests/test_common.py:604: AssertionError: assert None == '' where None = getattr((300a, 00c0) Beam Number IS: None, 'BeamNumber')

Seems like there is an extra space in "Beam Number" somewhere?

I also tested the storescu.py app with a local instance of OsiriX Lite and it worked properly.

This PR is ready to merge.

- Added `nr_ds` to make it easy to configure the number of datasets to use in the benchmark - Print the name of the DICOM file being used for the benchmark Note that `pynetdicom` performance is worse for larger DICOM files, such as `RTImageStorage.dcm`: ``` 9) C-STORE SCU/SCP transferred 100 total RTImageStorage.dcm datasets over 1 association(s) in 20.88 s 10) C-STORE DCMTK SCU/SCP transferred 100 total RTImageStorage.dcm datasets over 1 association(s) in 0.28 s ``` For `RTImageStorage.dcm`, `pynetdicom` is ~75x slower than DCMTK.

Instead of sleeping before every event, only sleep when there are no queued events to process. This ensures that queued events are processed as fast as possible. The `_run_loop_delay` setting now only affects the case where there are no queued events (i.e. the system is idle). After the performance optimization, `pynetdicom` is 23x faster than before when transferring `RTImageStorage.dcm`: New: ``` 1) C-STORE SCU transferred 100 total RTImageStorage.dcm datasets over 1 association(s) in 0.85 s 9) C-STORE SCU/SCP transferred 100 total RTImageStorage.dcm datasets over 1 association(s) in 1.43 s 10) C-STORE DCMTK SCU/SCP transferred 100 total RTImageStorage.dcm datasets over 1 association(s) in 0.29 s ``` Old: ``` 1) C-STORE SCU transferred 100 total RTImageStorage.dcm datasets over 1 association(s) in 19.69 s 9) C-STORE SCU/SCP transferred 100 total RTImageStorage.dcm datasets over 1 association(s) in 20.88 s 10) C-STORE DCMTK SCU/SCP transferred 100 total RTImageStorage.dcm datasets over 1 association(s) in 0.28 s ``` Now `pynetdicom` is only ~5x slower than DCMTK instead of ~75x.

When single-stepping the reactor, sleep between events so that test code has time to run.

- Prompt to use large or small dataset - Prompt for number of datasets to use (with default) - Run multiple benchmarks in a single run

- Display write option in output of `receive_store()` - Support running all tests, ranges of tests, or lists of tests

- Copy working `sleep()` timing pattern from `TestUPSFindServiceClass::test_scp_cancelled()` to 3 instances of `test_scp_cancelled()` in `test_service_qr.py`

codecov · 2021-06-23T23:07:55Z

Codecov Report

Merging #651 (c761804) into master (bc8fd99) will not change coverage.
The diff coverage is 100.00%.

@@            Coverage Diff            @@
##            master      #651   +/-   ##
=========================================
  Coverage   100.00%   100.00%           
=========================================
  Files           28        28           
  Lines         8609      8618    +9     
=========================================
+ Hits          8609      8618    +9

Impacted Files	Coverage Δ
pynetdicom/dul.py	`100.00% <100.00%> (ø)`
pynetdicom/events.py	`100.00% <100.00%> (ø)`

pynetdicom/events.py

pynetdicom/tests/benchmark_script.py

pynetdicom/events.py

scaramallion · 2021-06-23T23:28:28Z

Can you change these lines to:

for elem in iter(ds):
    if elem.VR == 'SQ':

To fix the typing error

scaramallion · 2021-06-23T23:34:33Z

You'll also need to add an explicit test for DULServiceProvider.stop_dul() (these lines) since it's harder to trigger now that the DUL reactor is looping so much faster.

scaramallion · 2021-06-23T23:43:25Z

The failing test in test_common is due to an issue in the current pydicom, it's been fixed in master.

- Add unit testing for `NotificationEvent::__str__()` - Add unit testing for `InterventionEvent::__str__()` - Remove `Event::__str__()` since it wasn't reliable/complete - Convert to f-strings in `benchmark_script.py` - Fix type error in `dsutils.py::pretty_dataset()`

mself · 2021-06-24T21:00:59Z

I don't understand the state machine well enough to create a new unit test for DULServiceProvider.stop_dul().

scaramallion · 2021-06-27T23:47:24Z

I don't understand the state machine well enough to create a new unit test for DULServiceProvider.stop_dul().

OK, let me think about it a bit

Test that `stop_dul()` returns `True` when in `Sta1`

mself · 2021-06-29T09:20:29Z

I added a unit test to verify that stop_dul() returns True when in Sta1. Other unit tests already cover the case where stop_dul() returns False when in other states. This should restore the code coverage to 100%.

mself · 2021-07-02T11:31:32Z

@scaramallion Can you please kick off the workflow for this PR to verify that all of the checks now pass? Thanks!

mself · 2021-07-08T09:01:02Z

@scaramallion Just checking in on this again :-)

mself · 2021-07-29T21:33:02Z

Hi there, @scaramallion. Any update on this? It's been a month. Thanks.

stefanoostwegel · 2021-11-09T12:44:18Z

I'm really looking forward for this improvement, when can we expect this to be released?

scaramallion · 2021-12-22T00:44:41Z

Thanks!

mself added 4 commits June 21, 2021 18:25

Correct output messages in receive_store_dcmtk()

7c3925e

Update .gitignore for PyCharm files

c52768d

mself mentioned this pull request Jun 21, 2021

storescu.py is ~35x slower than DCMTK's storescu when saving ultrasound studies #650

Closed

mself added 5 commits June 21, 2021 23:28

Add __str__() methods to event classes to aid debugging

78504e7

Fix for failure in test_fsm.py::TestState02::test_evt01()

87255db

When single-stepping the reactor, sleep between events so that test code has time to run.

Improvements to benchmark_script.py

1059840

- Prompt to use large or small dataset - Prompt for number of datasets to use (with default) - Run multiple benchmarks in a single run

More improvements to benchmark_script.py

f590b80

- Display write option in output of `receive_store()` - Support running all tests, ranges of tests, or lists of tests

Fix for failures in `test_scp_cancelled() unit tests

e262b90

- Copy working `sleep()` timing pattern from `TestUPSFindServiceClass::test_scp_cancelled()` to 3 instances of `test_scp_cancelled()` in `test_service_qr.py`

mself changed the title ~~[WIP] Improve DUL performance~~ [MRG] Improve DUL performance Jun 22, 2021