Slow transfer rates (this time with actual measurements)

All other questions regarding DCMTK

Moderator: Moderator Team

Message
Author
dimitri
Posts: 39
Joined: Mon, 2012-04-23, 13:43

Re: Slow transfer rates (this time with actual measurements)

#16 Post by dimitri »

We experimented with a much larger dataset to obtain meaningful timing values:
  • 000001_AAHScout
  • 000002_AAHScout-MPR
  • 000003_t2-loca
  • 000004_b1-map-xfl-sag-Amplitude
  • 000005_b1-map-xfl-sag-Phase
  • 000006_b1-map-xfl-sag-B1-Ampli-CP-mode
  • 000007_b1-map-xfl-sag-VR
  • 000008_b0-gre-field-mapping
  • 000009_b0-gre-field-mapping
  • 000010_t1-mp2rage-sag-iso0.75mm-INV1
  • 000011_t1-mp2rage-sag-iso0.75mm-INV1-PHS
  • 000012_t1-mp2rage-sag-iso0.75mm-T1-Images
  • 000013_t1-mp2rage-sag-iso0.75mm-UNI-DEN
  • 000014_t1-mp2rage-sag-iso0.75mm-UNI-Images
  • 000015_t1-mp2rage-sag-iso0.75mm-INV2
  • 000016_t1-mp2rage-sag-iso0.75mm-INV2-PHS
  • 000017_t2star-map-gre-sag-iso0.8mm-VCConline
  • 000018_t2star-map-gre-sag-iso0.8mm-VCConline
  • 000019_T2Star-Images
  • 000020_t2-tse-7T-cor-0.3x0.3x1.2mm-Block1
  • 000021_t2-tse-7T-cor-0.3x0.3x1.2mm-Block2
  • 000022_T2HR-fusionBlock1Block2
The characteristics of the whole dataset are:
  • number of files: 6028
  • total size: 1.7 GB
This is typical of our datasets in particular, and of neuroscience in general, with multiple repetitions of lower resolution images in multiple fMRI sequences.

An MRI operator was sending the above dataset repeatedly from the Siemens console, while I was changing the configuration of the storescp test instance for each transfer experiment. The transfer times were measured manually by the MRI operator, they do not include the "preparation time" of the Siemens console.


Experiment 1


With Nagle's algorithm, and with --ignore option to avoid the overhead of writing to the storage system.

Code: Select all

storescp --aetitle PtkDSU-NS-TEST --log-config log-config_test.cfg --disable-host-lookup --ignore 1104
We had to stop the transfer as it was painfully slow and we were worried the Siemens console might freeze::
  • 6'18" (6 minutes and 18 seconds) for 1865 files (instead of the total 6028), therefore very approx. 10 Mb/s

Experiment 2


Disabling Nagle's algorithm, and with --ignore option to avoid the overhead of writing to the storage system.

Code: Select all

export TCP_NODELAY=1
storescp --aetitle PtkDSU-NS-TEST --log-config log-config_test.cfg --disable-host-lookup --ignore 1104
The transfer rate is acceptable, although slower than in my previous tests. The larger number of files to transfer, 6028 instead of 399 previously, might be the reason.
  • 45" (45 seconds) for 1.7 GB, approx. 310 Mb/s

Experiment 3


Disabling Nagle's algorithm, with --ignore option to avoid the overhead of writing to the storage system, and -pdu 100000

Code: Select all

export TCP_NODELAY=1
storescp --aetitle PtkDSU-NS-TEST --log-config log-config_test.cfg --disable-host-lookup --ignore -pdu 100000 1104
Option -pdu 100000 does not make any difference.
  • 45" (45 seconds) for 1.7 GB, approx. 310 Mb/s
Should we test with -pdu 262144 instead? And would it make sense to test with -pdu 262144 without TCP_NODELAY=1?


Experiment 4


Disabling Nagle's algorithm, and without --ignore to take into account the overhead of writing to the storage system.

Code: Select all

export TCP_NODELAY=1
storescp --aetitle PtkDSU-NS-TEST --log-config log-config_test.cfg --disable-host-lookup --output-directory /storage/system/path/database/.TEST/.INCOMING 1104
Clearly writing lots of small files to our storage system, using NFS, takes its toll:
  • 2'13" (2 minutes and 13 seconds) for 1.7 GB, approx. 105 Mb/s
Some conclusions and remaining questions:
  • Very clearly Nagle's algorithm looks like the main culprit for the painfully slow transfers to our CentOS 6.5 DICOM server. With Nagle's algorithm enabled, transfers are slowed down by more than an order of magnitude. I'm not sure how to interpret that, the algorithm itself cannot be that bad so I guess this may be specific to our context.
  • is it expected that sending 6028 files instead of 399 files, with a similar total size of ~ 1.6 GB, is half as slow? Any suggestions on how to improve things on that front?
  • Our storage system, accessed from the DICOM server using NFS, is also slowing down transfers considerably. Of course, the large number of small files only makes things worse - we are highly aware of that.
  • Should I use test different values apart from -pdu 100000? Perhaps -pdu 262144?

J. Riesmeier
DCMTK Developer
Posts: 2501
Joined: Tue, 2011-05-03, 14:38
Location: Oldenburg, Germany
Contact:

Re: Slow transfer rates (this time with actual measurements)

#17 Post by J. Riesmeier »

Maybe, it would also make sense to analyze the log file created by storescp (with timestamps enabled, see "filelog.cfg") to see where the storescp possibly waits for the SCU to send data?

Also the --bit-preserving option (+B) of storescp might be worth a try, but I think you already did this.

dimitri
Posts: 39
Joined: Mon, 2012-04-23, 13:43

Re: Slow transfer rates (this time with actual measurements)

#18 Post by dimitri »

Yes, I had already tried --bit-preserving, but I can try again in this context.

Here is an excerpt of the verbose log file:

Code: Select all

[...]
2022-06-22 09:54:16.964 DEBUG: DUL: disabling Nagle algorithm as requested at runtime (TCP_NODELAY=1)
2022-06-22 09:54:16.965 DEBUG: Association Received: 10.15.1.69
2022-06-22 09:54:16.967 DEBUG: setting network send timeout to 60 seconds
2022-06-22 09:54:16.968 DEBUG: setting network receive timeout to 60 seconds
2022-06-22 09:54:16.969 DEBUG: PDU Type: Associate Request, PDU Length: 5156 + 6 bytes PDU header
[...]
2022-06-22 09:54:16.970 DEBUG: Parsing an A-ASSOCIATE PDU
2022-06-22 09:54:16.972  INFO: Association Received
2022-06-22 09:54:16.973 DEBUG: Parameters:
2022-06-22 09:54:16.973 DEBUG: ====================== BEGIN A-ASSOCIATE-RQ =====================
2022-06-22 09:54:16.973 DEBUG: Our Implementation Class UID:      1.2.276.0.7230010.3.0.3.6.7
2022-06-22 09:54:16.973 DEBUG: Our Implementation Version Name:   OFFIS_DCMTK_367
2022-06-22 09:54:16.973 DEBUG: Their Implementation Class UID:    1.3.12.2.1107.5.2
2022-06-22 09:54:16.973 DEBUG: Their Implementation Version Name: MR_VB17A
2022-06-22 09:54:16.973 DEBUG: Application Context Name:    1.2.840.10008.3.1.1.1
2022-06-22 09:54:16.973 DEBUG: Calling Application Name:    MRC18917
2022-06-22 09:54:16.973 DEBUG: Called Application Name:     PtkDSU-NS-TEST
2022-06-22 09:54:16.973 DEBUG: Responding Application Name: 
2022-06-22 09:54:16.973 DEBUG: Our Max PDU Receive Size:    16384
2022-06-22 09:54:16.973 DEBUG: Their Max PDU Receive Size:  262144
2022-06-22 09:54:16.973 DEBUG: Presentation Contexts
[...]
2022-06-22 09:54:16.973 DEBUG: ======================= END A-ASSOCIATE-RQ ======================
2022-06-22 09:54:16.980 DEBUG: Constructing Associate AC PDU
2022-06-22 09:54:16.981  INFO: Association Acknowledged (Max Send PDV: 131060)
2022-06-22 09:54:16.982 DEBUG: ====================== BEGIN A-ASSOCIATE-AC =====================
2022-06-22 09:54:16.982 DEBUG: Our Implementation Class UID:      1.2.276.0.7230010.3.0.3.6.7
2022-06-22 09:54:16.982 DEBUG: Our Implementation Version Name:   OFFIS_DCMTK_367
2022-06-22 09:54:16.982 DEBUG: Their Implementation Class UID:    1.3.12.2.1107.5.2
2022-06-22 09:54:16.982 DEBUG: Their Implementation Version Name: MR_VB17A
2022-06-22 09:54:16.982 DEBUG: Application Context Name:    1.2.840.10008.3.1.1.1
2022-06-22 09:54:16.982 DEBUG: Calling Application Name:    MRC18917
2022-06-22 09:54:16.982 DEBUG: Called Application Name:     PtkDSU-NS-TEST
2022-06-22 09:54:16.982 DEBUG: Responding Application Name: PtkDSU-NS-TEST
2022-06-22 09:54:16.982 DEBUG: Our Max PDU Receive Size:    16384
2022-06-22 09:54:16.982 DEBUG: Their Max PDU Receive Size:  262144
[...]
2022-06-22 09:54:16.982 DEBUG: Requested Extended Negotiation: none
2022-06-22 09:54:16.982 DEBUG: Accepted Extended Negotiation:  none
2022-06-22 09:54:16.982 DEBUG: Requested User Identity Negotiation: none
2022-06-22 09:54:16.982 DEBUG: User Identity Negotiation Response:  none
2022-06-22 09:54:16.982 DEBUG: ======================= END A-ASSOCIATE-AC ======================
2022-06-22 09:54:16.987 DEBUG: DcmDataset::read() TransferSyntax="Little Endian Implicit"
2022-06-22 09:54:16.988  INFO: Received Store Request
2022-06-22 09:54:16.989 DEBUG: ===================== INCOMING DIMSE MESSAGE ====================
2022-06-22 09:54:16.989 DEBUG: Message Type                  : C-STORE RQ
2022-06-22 09:54:16.989 DEBUG: Presentation Context ID       : 5
2022-06-22 09:54:16.989 DEBUG: Message ID                    : 13782
2022-06-22 09:54:16.989 DEBUG: Affected SOP Class UID        : MRImageStorage
2022-06-22 09:54:16.989 DEBUG: Affected SOP Instance UID     : 1.3.12.2.1107.5.2.34.18917.2022051613594569979260117
2022-06-22 09:54:16.989 DEBUG: Data Set                      : present
2022-06-22 09:54:16.989 DEBUG: Priority                      : medium
2022-06-22 09:54:16.989 DEBUG: ======================= END DIMSE MESSAGE =======================
2022-06-22 09:54:16.990 DEBUG: DcmDataset::read() TransferSyntax="Little Endian Explicit"
[...]
2022-06-22 09:55:04.880 DEBUG: DcmDataset::read() TransferSyntax="Little Endian Implicit"
2022-06-22 09:55:04.881  INFO: Received Store Request
2022-06-22 09:55:04.881 DEBUG: ===================== INCOMING DIMSE MESSAGE ====================
2022-06-22 09:55:04.881 DEBUG: Message Type                  : C-STORE RQ
2022-06-22 09:55:04.881 DEBUG: Presentation Context ID       : 5
2022-06-22 09:55:04.881 DEBUG: Message ID                    : 19808
2022-06-22 09:55:04.881 DEBUG: Affected SOP Class UID        : MRImageStorage
2022-06-22 09:55:04.881 DEBUG: Affected SOP Instance UID     : 1.3.12.2.1107.5.2.34.18917.30000022051607504345400000223
2022-06-22 09:55:04.881 DEBUG: Data Set                      : present
2022-06-22 09:55:04.881 DEBUG: Priority                      : medium
2022-06-22 09:55:04.881 DEBUG: ======================= END DIMSE MESSAGE =======================
2022-06-22 09:55:04.882 DEBUG: DcmDataset::read() TransferSyntax="Little Endian Explicit"
2022-06-22 09:55:04.895 DEBUG: DcmDataset::read() TransferSyntax="Little Endian Implicit"
2022-06-22 09:55:04.896  INFO: Received Store Request
2022-06-22 09:55:04.896 DEBUG: ===================== INCOMING DIMSE MESSAGE ====================
2022-06-22 09:55:04.896 DEBUG: Message Type                  : C-STORE RQ
2022-06-22 09:55:04.896 DEBUG: Presentation Context ID       : 5
2022-06-22 09:55:04.896 DEBUG: Message ID                    : 19809
2022-06-22 09:55:04.896 DEBUG: Affected SOP Class UID        : MRImageStorage
2022-06-22 09:55:04.896 DEBUG: Affected SOP Instance UID     : 1.3.12.2.1107.5.2.34.18917.30000022051607504345400000224
2022-06-22 09:55:04.896 DEBUG: Data Set                      : present
2022-06-22 09:55:04.896 DEBUG: Priority                      : medium
2022-06-22 09:55:04.896 DEBUG: ======================= END DIMSE MESSAGE =======================
2022-06-22 09:55:04.897 DEBUG: DcmDataset::read() TransferSyntax="Little Endian Explicit"
2022-06-22 09:55:04.909  INFO: Association Release
[...]

dimitri
Posts: 39
Joined: Mon, 2012-04-23, 13:43

Re: Slow transfer rates (this time with actual measurements)

#19 Post by dimitri »

For what it is worth, the operators tell me that data are mosaic'ed whenever possible, depending on the series. Therefore, I doubt we can improve speed by reducing the number of data chunks sent for the whole dataset:

Code: Select all

| series                                       | files |
+----------------------------------------------+-------+
| 000001_AAHScout                              |   128 |
| 000002_AAHScout-MPR                          |     4 |
| 000003_t2-loca                               |     6 |
| 000004_b1-map-xfl-sag-Amplitude              |    44 |
| 000005_b1-map-xfl-sag-Phase                  |    44 |
| 000006_b1-map-xfl-sag-B1-Ampli-CP-mode       |    22 |
| 000007_b1-map-xfl-sag-VR                     |    22 |
| 000008_b0-gre-field-mapping                  |    44 |
| 000009_b0-gre-field-mapping                  |    22 |
| 000010_t1-mp2rage-sag-iso0.75mm-INV1         |   224 |
| 000011_t1-mp2rage-sag-iso0.75mm-INV1-PHS     |   224 |
| 000012_t1-mp2rage-sag-iso0.75mm-T1-Images    |   224 |
| 000013_t1-mp2rage-sag-iso0.75mm-UNI-DEN      |   224 |
| 000014_t1-mp2rage-sag-iso0.75mm-UNI-Images   |   224 |
| 000015_t1-mp2rage-sag-iso0.75mm-INV2         |   224 |
| 000016_t1-mp2rage-sag-iso0.75mm-INV2-PHS     |   224 |
| 000017_t2star-map-gre-sag-iso0.8mm-VCConline |  1920 |
| 000018_t2star-map-gre-sag-iso0.8mm-VCConline |  1920 |
| 000019_T2Star-Images                         |   192 |
| 000020_t2-tse-7T-cor-0.3x0.3x1.2mm-Block1    |    23 |
| 000021_t2-tse-7T-cor-0.3x0.3x1.2mm-Block2    |    23 |
| 000022_T2HR-fusionBlock1Block2               |    46 |

Post Reply

Who is online

Users browsing this forum: Bing [Bot] and 1 guest