storescp much slower than scp (copy through ssh)

All other questions regarding DCMTK

Moderator: Moderator Team

Message
Author
martinrame
Posts: 347
Joined: Mon, 2009-02-23, 19:57

storescp much slower than scp (copy through ssh)

#1 Post by martinrame »

Hi, I'm trying to find the cause of a very slow storescp behavior.

On a VPS (Digital Ocean, 4v cpu, 8gb RAM, 1tb SSD drive, Ubuntu 16.04 64bit) I run:

Code: Select all

storescp -dhl --ignore 105
then in my PC I execute two tests:

Test 1: copy a file using "scp":

Code: Select all

time scp ~/dicom/IM_0020 vps-server:/home/leonardo/IM_0020                                                             100% 3453KB 690.5KB/s   00:05
scp ~/dicom/IM_0020 vps-server:/home/leonardo  0.01s user 0.00s system 0% cpu 12.007 total
As you can see it takes 12sec to finish.

Test 2: send the same file using "dcmsend":

Code: Select all

./dcmsend -v -aet TEST -aec TEST 151.220.9.94 105 ~/dicom/IM_0020  0.04s user 0.01s system 0% cpu 22.799 total
Now it takes 22.8seconds.

The storescp server is run using --ignore and -dhl, so, no disk i/o can be slowing down the storage and the -dhl prevents the dns lookups.

What else can be causing the slowness of storescp?.

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

Re: storescp much slower than scp (copy through ssh)

#2 Post by J. Riesmeier »

Which version of the DCMTK tools do you use? There were some changes regarding the TCP/IP network options in the last couple of years/months (see CHANGES file or git log).

martinrame
Posts: 347
Joined: Mon, 2009-02-23, 19:57

Re: storescp much slower than scp (copy through ssh)

#3 Post by martinrame »

I'm using

Code: Select all

storescp v3.6.1 2015-02-17
. I'll try with the latest version.

martinrame
Posts: 347
Joined: Mon, 2009-02-23, 19:57

Re: storescp much slower than scp (copy through ssh)

#4 Post by martinrame »

Ok, now I replaced storescp with the 3.6.4 version, but I still get similar results. I played with -pdu (ranging from 4096 up to 131072), but the whole process still takes ~23 seconds to finish.

martinrame
Posts: 347
Joined: Mon, 2009-02-23, 19:57

Re: storescp much slower than scp (copy through ssh)

#5 Post by martinrame »

I played with the environment variable TCP_BUFFER_LENGTH, trying with these values:

1. export TCP_BUFFER_LENGTH=1024

It takes forever, I had to ctrl+c storescp.

2. export TCP_BUFFER_LENGTH=129076

It took 22.318s, the same as using the default values.

3. export TCP_BUFFER_LENGTH=229076

It took 22.681s

4. export TCP_BUFFER_LENGTH=129075

It took 21.760s

5. export TCP_BUFFER_LENGTH=85000

It took 22.289s

My conclussion is changing TCP_BUFFER_LENGTH to a different value than default doesn't improves the situation.

martinrame
Posts: 347
Joined: Mon, 2009-02-23, 19:57

Re: storescp much slower than scp (copy through ssh)

#6 Post by martinrame »

The next test was changing the environment variable TCP_NODELAY.

1. export TCP_NODELAY=1:

Result: 24.748s

2. export TCP_NODELAY=0 (default):

Result: 22.55s.

The best performance was obtained using the default values. Still far behind scp (do not confuse dicom scp with ssh scp, the second is the one I'm using to copy the file to the remote server.).

martinrame
Posts: 347
Joined: Mon, 2009-02-23, 19:57

Re: storescp much slower than scp (copy through ssh)

#7 Post by martinrame »

The latest test was using a log file to log the process timestamp, here it is:

Code: Select all

2019-05-11 14:54:36.583 DEBUG - storescp - $dcmtk: storescp v3.6.4 2018-11-29 $
2019-05-11 14:54:36.583 DEBUG - storescp - 
2019-05-11 14:54:36.584 DEBUG - dcmdata  - DcmDataDictionary: Loading file: /home/leonardo/scp/config/dicom.dic
2019-05-11 14:54:40.700 DEBUG - dcmnet   - Association Received: 45.132.419.4
2019-05-11 14:54:40.700 DEBUG - dcmnet   - setting network send timeout to 60 seconds
2019-05-11 14:54:40.700 DEBUG - dcmnet   - setting network receive timeout to 60 seconds
2019-05-11 14:54:40.700 DEBUG - dcmnet   - PDU Type: Associate Request, PDU Length: 261 + 6 bytes PDU header
2019-05-11 14:54:40.700 DEBUG - dcmnet   -   01  00  00  00  01  05  00  01  00  00  54  45  53  54  20  20
2019-05-11 14:54:40.700 DEBUG - dcmnet   -   20  20  20  20  20  20  20  20  20  20  54  45  53  54  20  20
2019-05-11 14:54:40.700 DEBUG - dcmnet   -   20  20  20  20  20  20  20  20  20  20  00  00  00  00  00  00
2019-05-11 14:54:40.700 DEBUG - dcmnet   -   00  00  00  00  00  00  00  00  00  00  00  00  00  00  00  00
2019-05-11 14:54:40.700 DEBUG - dcmnet   -   00  00  00  00  00  00  00  00  00  00  10  00  00  15  31  2e
2019-05-11 14:54:40.700 DEBUG - dcmnet   -   32  2e  38  34  30  2e  31  30  30  30  38  2e  33  2e  31  2e
2019-05-11 14:54:40.700 DEBUG - dcmnet   -   31  2e  31  20  00  00  66  01  00  ff  00  30  00  00  1b  31
2019-05-11 14:54:40.700 DEBUG - dcmnet   -   2e  32  2e  38  34  30  2e  31  30  30  30  38  2e  35  2e  31
2019-05-11 14:54:40.700 DEBUG - dcmnet   -   2e  34  2e  31  2e  31  2e  34  2e  31  40  00  00  13  31  2e
2019-05-11 14:54:40.700 DEBUG - dcmnet   -   32  2e  38  34  30  2e  31  30  30  30  38  2e  31  2e  32  2e
2019-05-11 14:54:40.700 DEBUG - dcmnet   -   31  40  00  00  13  31  2e  32  2e  38  34  30  2e  31  30  30
2019-05-11 14:54:40.700 DEBUG - dcmnet   -   30  38  2e  31  2e  32  2e  32  40  00  00  11  31  2e  32  2e
2019-05-11 14:54:40.700 DEBUG - dcmnet   -   38  34  30  2e  31  30  30  30  38  2e  31  2e  32  50  00  00
2019-05-11 14:54:40.700 DEBUG - dcmnet   -   3a  51  00  00  04  00  00  40  00  52  00  00  1b  31  2e  32
2019-05-11 14:54:40.700 DEBUG - dcmnet   -   2e  32  37  36  2e  30  2e  37  32  33  30  30  31  30  2e  33
2019-05-11 14:54:40.700 DEBUG - dcmnet   -   2e  30  2e  33  2e  36  2e  31  55  00  00  0f  4f  46  46  49
2019-05-11 14:54:40.700 DEBUG - dcmnet   -   53  5f  44  43  4d  54  4b  5f  33  36  31
2019-05-11 14:54:40.700 DEBUG - dcmnet   - Parsing an A-ASSOCIATE PDU
2019-05-11 14:54:40.700  INFO - storescp - Association Received
2019-05-11 14:54:40.700 DEBUG - storescp - Parameters:
2019-05-11 14:54:40.700 DEBUG - storescp - ====================== BEGIN A-ASSOCIATE-RQ =====================
2019-05-11 14:54:40.700 DEBUG - storescp - Our Implementation Class UID:      1.2.276.0.7230010.3.0.3.6.4
2019-05-11 14:54:40.700 DEBUG - storescp - Our Implementation Version Name:   OFFIS_DCMTK_364
2019-05-11 14:54:40.700 DEBUG - storescp - Their Implementation Class UID:    1.2.276.0.7230010.3.0.3.6.1
2019-05-11 14:54:40.700 DEBUG - storescp - Their Implementation Version Name: OFFIS_DCMTK_361
2019-05-11 14:54:40.700 DEBUG - storescp - Application Context Name:    1.2.840.10008.3.1.1.1
2019-05-11 14:54:40.700 DEBUG - storescp - Calling Application Name:    TEST
2019-05-11 14:54:40.700 DEBUG - storescp - Called Application Name:     TEST
2019-05-11 14:54:40.700 DEBUG - storescp - Responding Application Name: 
2019-05-11 14:54:40.700 DEBUG - storescp - Our Max PDU Receive Size:    16384
2019-05-11 14:54:40.700 DEBUG - storescp - Their Max PDU Receive Size:  16384
2019-05-11 14:54:40.700 DEBUG - storescp - Presentation Contexts:
2019-05-11 14:54:40.700 DEBUG - storescp -   Context ID:        1 (Proposed)
2019-05-11 14:54:40.700 DEBUG - storescp -     Abstract Syntax: =EnhancedMRImageStorage
2019-05-11 14:54:40.700 DEBUG - storescp -     Proposed SCP/SCU Role: Default
2019-05-11 14:54:40.700 DEBUG - storescp -     Proposed Transfer Syntax(es):
2019-05-11 14:54:40.700 DEBUG - storescp -       =LittleEndianExplicit
2019-05-11 14:54:40.700 DEBUG - storescp -       =BigEndianExplicit
2019-05-11 14:54:40.700 DEBUG - storescp -       =LittleEndianImplicit
2019-05-11 14:54:40.700 DEBUG - storescp - Requested Extended Negotiation: none
2019-05-11 14:54:40.700 DEBUG - storescp - Accepted Extended Negotiation:  none
2019-05-11 14:54:40.700 DEBUG - storescp - Requested User Identity Negotiation: none
2019-05-11 14:54:40.700 DEBUG - storescp - User Identity Negotiation Response:  none
2019-05-11 14:54:40.700 DEBUG - storescp - ======================= END A-ASSOCIATE-RQ ======================
2019-05-11 14:54:40.700 DEBUG - dcmnet   - Constructing Associate AC PDU
2019-05-11 14:54:40.700  INFO - storescp - Association Acknowledged (Max Send PDV: 16372)
2019-05-11 14:54:40.700 DEBUG - storescp - ====================== BEGIN A-ASSOCIATE-AC =====================
2019-05-11 14:54:40.700 DEBUG - storescp - Our Implementation Class UID:      1.2.276.0.7230010.3.0.3.6.4
2019-05-11 14:54:40.700 DEBUG - storescp - Our Implementation Version Name:   OFFIS_DCMTK_364
2019-05-11 14:54:40.700 DEBUG - storescp - Their Implementation Class UID:    1.2.276.0.7230010.3.0.3.6.1
2019-05-11 14:54:40.700 DEBUG - storescp - Their Implementation Version Name: OFFIS_DCMTK_361
2019-05-11 14:54:40.700 DEBUG - storescp - Application Context Name:    1.2.840.10008.3.1.1.1
2019-05-11 14:54:40.700 DEBUG - storescp - Calling Application Name:    TEST
2019-05-11 14:54:40.700 DEBUG - storescp - Called Application Name:     TEST
2019-05-11 14:54:40.700 DEBUG - storescp - Responding Application Name: TEST
2019-05-11 14:54:40.700 DEBUG - storescp - Our Max PDU Receive Size:    16384
2019-05-11 14:54:40.700 DEBUG - storescp - Their Max PDU Receive Size:  16384
2019-05-11 14:54:40.700 DEBUG - storescp - Presentation Contexts:
2019-05-11 14:54:40.700 DEBUG - storescp -   Context ID:        1 (Accepted)
2019-05-11 14:54:40.700 DEBUG - storescp -     Abstract Syntax: =EnhancedMRImageStorage
2019-05-11 14:54:40.700 DEBUG - storescp -     Proposed SCP/SCU Role: Default
2019-05-11 14:54:40.700 DEBUG - storescp -     Accepted SCP/SCU Role: Default
2019-05-11 14:54:40.700 DEBUG - storescp -     Accepted Transfer Syntax: =LittleEndianExplicit
2019-05-11 14:54:40.700 DEBUG - storescp - Requested Extended Negotiation: none
2019-05-11 14:54:40.700 DEBUG - storescp - Accepted Extended Negotiation:  none
2019-05-11 14:54:40.700 DEBUG - storescp - Requested User Identity Negotiation: none
2019-05-11 14:54:40.700 DEBUG - storescp - User Identity Negotiation Response:  none
2019-05-11 14:54:40.700 DEBUG - storescp - ======================= END A-ASSOCIATE-AC ======================
2019-05-11 14:54:40.926 DEBUG - dcmdata  - DcmDataset::read() TransferSyntax="Little Endian Implicit"
2019-05-11 14:54:40.926  INFO - storescp - Received Store Request
2019-05-11 14:54:40.926 DEBUG - storescp - ===================== INCOMING DIMSE MESSAGE ====================
2019-05-11 14:54:40.926 DEBUG - storescp - Message Type                  : C-STORE RQ
2019-05-11 14:54:40.926 DEBUG - storescp - Presentation Context ID       : 1
2019-05-11 14:54:40.926 DEBUG - storescp - Message ID                    : 1
2019-05-11 14:54:40.926 DEBUG - storescp - Affected SOP Class UID        : EnhancedMRImageStorage
2019-05-11 14:54:40.926 DEBUG - storescp - Affected SOP Instance UID     : 1.3.46.670589.11.33493.5.20.1.1.9096.2018050109101507058
2019-05-11 14:54:40.926 DEBUG - storescp - Data Set                      : present
2019-05-11 14:54:40.926 DEBUG - storescp - Priority                      : low
2019-05-11 14:54:40.926 DEBUG - storescp - ======================= END DIMSE MESSAGE =======================
2019-05-11 14:54:41.278 DEBUG - dcmdata  - DcmDataset::read() TransferSyntax="Little Endian Explicit"
2019-05-11 14:55:02.942  INFO - storescp - Association Release
As you can see, the only noticeable delay is between 14:54:41.278 and 14:55:02.942, but there's no information between those lines.

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

Re: storescp much slower than scp (copy through ssh)

#8 Post by J. Riesmeier »

You could enable TRACE log output (at least for the dcmnet module since the output for the dcmdata module might be annoying in this context). You might also want to test the +B (--bit-preserving) option of storescp.

martinrame
Posts: 347
Joined: Mon, 2009-02-23, 19:57

Re: storescp much slower than scp (copy through ssh)

#9 Post by martinrame »

Ok, with --bit-preserving nothing changed.

Here is the trace:

Code: Select all

2019-05-13 08:24:26.679 DEBUG - storescp - $dcmtk: storescp v3.6.4 2018-11-29 $
2019-05-13 08:24:26.679 DEBUG - storescp - 
2019-05-13 08:24:26.680 DEBUG - dcmdata  - DcmDataDictionary: Loading file: /home/informemedico/scp/config/dicom.dic
2019-05-13 08:24:31.691 TRACE - dcmnet   - Timeout while waiting for incoming network data
2019-05-13 08:24:33.806 TRACE - dcmnet   - Receiving data via select()
2019-05-13 08:24:33.806 TRACE - dcmnet   - checking whether environment variable TCP_BUFFER_LENGTH is set
2019-05-13 08:24:33.807 TRACE - dcmnet   -   environment variable TCP_BUFFER_LENGTH not set, using the system defaults
2019-05-13 08:24:33.807 TRACE - dcmnet   - checking whether environment variable TCP_NODELAY is set
2019-05-13 08:24:33.807 TRACE - dcmnet   -   environment variable TCP_NODELAY not set, using the default value (0)
2019-05-13 08:24:33.807 DEBUG - dcmnet   - Association Received: 45.234.119.3
2019-05-13 08:24:33.807 DEBUG - dcmnet   - setting network send timeout to 60 seconds
2019-05-13 08:24:33.807 DEBUG - dcmnet   - setting network receive timeout to 60 seconds
2019-05-13 08:24:33.807 TRACE - dcmnet   - DUL  FSM Table: State: 1 Event: 4
2019-05-13 08:24:33.807 TRACE - dcmnet   - DUL  Event:  Transport connection indication
2019-05-13 08:24:33.807 TRACE - dcmnet   - DUL  Action: AE 5 Transport Connect Response
2019-05-13 08:24:33.807 TRACE - dcmnet   - setting timeout for first PDU to be read to 30 seconds
2019-05-13 08:24:33.807 TRACE - dcmnet   - Read PDU HEAD TCP: 01 00 00 00 01 05
2019-05-13 08:24:33.807 TRACE - dcmnet   - Read PDU HEAD TCP: type: 01, length: 261 (105)
2019-05-13 08:24:33.807 TRACE - dcmnet   - DUL  FSM Table: State: 2 Event: 5
2019-05-13 08:24:33.807 TRACE - dcmnet   - DUL  Event:  A-ASSOCIATE-RQ PDU (on transport)
2019-05-13 08:24:33.807 TRACE - dcmnet   - DUL  Action: AE 6 Examine Associate Request
2019-05-13 08:24:33.807 DEBUG - dcmnet   - PDU Type: Associate Request, PDU Length: 261 + 6 bytes PDU header
2019-05-13 08:24:33.807 DEBUG - dcmnet   -   01  00  00  00  01  05  00  01  00  00  54  45  53  54  20  20
2019-05-13 08:24:33.807 DEBUG - dcmnet   -   20  20  20  20  20  20  20  20  20  20  54  45  53  54  20  20
2019-05-13 08:24:33.807 DEBUG - dcmnet   -   20  20  20  20  20  20  20  20  20  20  00  00  00  00  00  00
2019-05-13 08:24:33.807 DEBUG - dcmnet   -   00  00  00  00  00  00  00  00  00  00  00  00  00  00  00  00
2019-05-13 08:24:33.807 DEBUG - dcmnet   -   00  00  00  00  00  00  00  00  00  00  10  00  00  15  31  2e
2019-05-13 08:24:33.807 DEBUG - dcmnet   -   32  2e  38  34  30  2e  31  30  30  30  38  2e  33  2e  31  2e
2019-05-13 08:24:33.807 DEBUG - dcmnet   -   31  2e  31  20  00  00  66  01  00  ff  00  30  00  00  1b  31
2019-05-13 08:24:33.807 DEBUG - dcmnet   -   2e  32  2e  38  34  30  2e  31  30  30  30  38  2e  35  2e  31
2019-05-13 08:24:33.807 DEBUG - dcmnet   -   2e  34  2e  31  2e  31  2e  34  2e  31  40  00  00  13  31  2e
2019-05-13 08:24:33.807 DEBUG - dcmnet   -   32  2e  38  34  30  2e  31  30  30  30  38  2e  31  2e  32  2e
2019-05-13 08:24:33.807 DEBUG - dcmnet   -   31  40  00  00  13  31  2e  32  2e  38  34  30  2e  31  30  30
2019-05-13 08:24:33.807 DEBUG - dcmnet   -   30  38  2e  31  2e  32  2e  32  40  00  00  11  31  2e  32  2e
2019-05-13 08:24:33.807 DEBUG - dcmnet   -   38  34  30  2e  31  30  30  30  38  2e  31  2e  32  50  00  00
2019-05-13 08:24:33.807 DEBUG - dcmnet   -   3a  51  00  00  04  00  00  40  00  52  00  00  1b  31  2e  32
2019-05-13 08:24:33.807 DEBUG - dcmnet   -   2e  32  37  36  2e  30  2e  37  32  33  30  30  31  30  2e  33
2019-05-13 08:24:33.807 DEBUG - dcmnet   -   2e  30  2e  33  2e  36  2e  34  55  00  00  0f  4f  46  46  49
2019-05-13 08:24:33.807 DEBUG - dcmnet   -   53  5f  44  43  4d  54  4b  5f  33  36  34
2019-05-13 08:24:33.807 DEBUG - dcmnet   - Parsing an A-ASSOCIATE PDU
2019-05-13 08:24:33.807 TRACE - dcmnet   - PDU type: 1 (A-ASSOCIATE RQ), PDU Length: 261
2019-05-13 08:24:33.807 TRACE - dcmnet   - DICOM Protocol: 1
2019-05-13 08:24:33.807 TRACE - dcmnet   - Called AP Title:  TEST
2019-05-13 08:24:33.807 TRACE - dcmnet   - Calling AP Title: TEST
2019-05-13 08:24:33.807 TRACE - dcmnet   - Parsing remaining 193 bytes of A-ASSOCIATE PDU
2019-05-13 08:24:33.807 TRACE - dcmnet   - Next item type: 10
2019-05-13 08:24:33.807 TRACE - dcmnet   - Subitem parse: Type 10, Length 0021, Content: 1.2.840.10008.3.1.1.1
2019-05-13 08:24:33.807 TRACE - dcmnet   - Successfully parsed Application Context
2019-05-13 08:24:33.807 TRACE - dcmnet   - Parsing remaining 168 bytes of A-ASSOCIATE PDU
2019-05-13 08:24:33.807 TRACE - dcmnet   - Next item type: 20
2019-05-13 08:24:33.807 TRACE - dcmnet   - Parsing Presentation Context: (20), Length: 102
2019-05-13 08:24:33.807 TRACE - dcmnet   - Presentation Context ID: 01
2019-05-13 08:24:33.807 TRACE - dcmnet   - Parsing remaining 98 bytes of Presentation Context
2019-05-13 08:24:33.807 TRACE - dcmnet   - Next item type: 30
2019-05-13 08:24:33.807 TRACE - dcmnet   - Subitem parse: Type 30, Length 0027, Content: 1.2.840.10008.5.1.4.1.1.4.1
2019-05-13 08:24:33.807 TRACE - dcmnet   - Successfully parsed Abstract Syntax
2019-05-13 08:24:33.807 TRACE - dcmnet   - Parsing remaining 67 bytes of Presentation Context
2019-05-13 08:24:33.807 TRACE - dcmnet   - Next item type: 40
2019-05-13 08:24:33.807 TRACE - dcmnet   - Subitem parse: Type 40, Length 0019, Content: 1.2.840.10008.1.2.1
2019-05-13 08:24:33.807 TRACE - dcmnet   - Successfully parsed Transfer Syntax
2019-05-13 08:24:33.808 TRACE - dcmnet   - Parsing remaining 44 bytes of Presentation Context
2019-05-13 08:24:33.808 TRACE - dcmnet   - Next item type: 40
2019-05-13 08:24:33.808 TRACE - dcmnet   - Subitem parse: Type 40, Length 0019, Content: 1.2.840.10008.1.2.2
2019-05-13 08:24:33.808 TRACE - dcmnet   - Successfully parsed Transfer Syntax
2019-05-13 08:24:33.808 TRACE - dcmnet   - Parsing remaining 21 bytes of Presentation Context
2019-05-13 08:24:33.808 TRACE - dcmnet   - Next item type: 40

--- BREAK BECAUSE OF ALLOWED MESSAGE SIZE EXCEEDS 60000 CHARACTERS ---

2019-05-13 08:24:50.445 TRACE - dcmdata  - DcmItem::read() returns error = I/O suspension or premature end of stream
2019-05-13 08:24:50.445 TRACE - dcmdata  - DcmDataset::read() returns error = I/O suspension or premature end of stream
2019-05-13 08:24:50.445 TRACE - dcmnet   - DIMSE receiveDataSetInMemory: 16372 bytes read (last: NO)
2019-05-13 08:24:50.445 TRACE - dcmnet   - Read PDU HEAD TCP: 04 00 00 00 3f fa
2019-05-13 08:24:50.445 TRACE - dcmnet   - Read PDU HEAD TCP: type: 04, length: 16378 (3ffa)
2019-05-13 08:24:50.445 TRACE - dcmnet   - DUL  FSM Table: State: 6 Event: 9
2019-05-13 08:24:50.445 TRACE - dcmnet   - DUL  Event:  P-DATA-TF PDU (on transport)
2019-05-13 08:24:50.445 TRACE - dcmnet   - DUL  Action: DT 2 Indicate P DATA PDU Received
2019-05-13 08:24:50.547 TRACE - dcmdata  - DcmItem::read() returns error = I/O suspension or premature end of stream
2019-05-13 08:24:50.547 TRACE - dcmdata  - DcmDataset::read() returns error = I/O suspension or premature end of stream
2019-05-13 08:24:50.547 TRACE - dcmnet   - DIMSE receiveDataSetInMemory: 16372 bytes read (last: NO)
2019-05-13 08:24:50.547 TRACE - dcmnet   - Read PDU HEAD TCP: 04 00 00 00 3f fa
2019-05-13 08:24:50.547 TRACE - dcmnet   - Read PDU HEAD TCP: type: 04, length: 16378 (3ffa)
2019-05-13 08:24:50.547 TRACE - dcmnet   - DUL  FSM Table: State: 6 Event: 9
2019-05-13 08:24:50.547 TRACE - dcmnet   - DUL  Event:  P-DATA-TF PDU (on transport)
2019-05-13 08:24:50.547 TRACE - dcmnet   - DUL  Action: DT 2 Indicate P DATA PDU Received
2019-05-13 08:24:50.640 TRACE - dcmdata  - DcmItem::read() returns error = I/O suspension or premature end of stream
2019-05-13 08:24:50.640 TRACE - dcmdata  - DcmDataset::read() returns error = I/O suspension or premature end of stream
2019-05-13 08:24:50.640 TRACE - dcmnet   - DIMSE receiveDataSetInMemory: 16372 bytes read (last: NO)
2019-05-13 08:24:50.640 TRACE - dcmnet   - Read PDU HEAD TCP: 04 00 00 00 3f fa
2019-05-13 08:24:50.640 TRACE - dcmnet   - Read PDU HEAD TCP: type: 04, length: 16378 (3ffa)
2019-05-13 08:24:50.640 TRACE - dcmnet   - DUL  FSM Table: State: 6 Event: 9
2019-05-13 08:24:50.640 TRACE - dcmnet   - DUL  Event:  P-DATA-TF PDU (on transport)
2019-05-13 08:24:50.640 TRACE - dcmnet   - DUL  Action: DT 2 Indicate P DATA PDU Received
2019-05-13 08:24:50.733 TRACE - dcmdata  - DcmItem::read() returns error = I/O suspension or premature end of stream
2019-05-13 08:24:50.733 TRACE - dcmdata  - DcmDataset::read() returns error = I/O suspension or premature end of stream
2019-05-13 08:24:50.733 TRACE - dcmnet   - DIMSE receiveDataSetInMemory: 16372 bytes read (last: NO)
2019-05-13 08:24:50.733 TRACE - dcmnet   - Read PDU HEAD TCP: 04 00 00 00 3f fa
2019-05-13 08:24:50.733 TRACE - dcmnet   - Read PDU HEAD TCP: type: 04, length: 16378 (3ffa)
2019-05-13 08:24:50.733 TRACE - dcmnet   - DUL  FSM Table: State: 6 Event: 9
2019-05-13 08:24:50.733 TRACE - dcmnet   - DUL  Event:  P-DATA-TF PDU (on transport)
2019-05-13 08:24:50.733 TRACE - dcmnet   - DUL  Action: DT 2 Indicate P DATA PDU Received
2019-05-13 08:24:50.834 TRACE - dcmdata  - DcmItem::read() returns error = I/O suspension or premature end of stream
2019-05-13 08:24:50.834 TRACE - dcmdata  - DcmDataset::read() returns error = I/O suspension or premature end of stream
2019-05-13 08:24:50.834 TRACE - dcmnet   - DIMSE receiveDataSetInMemory: 16372 bytes read (last: NO)
2019-05-13 08:24:50.834 TRACE - dcmnet   - Read PDU HEAD TCP: 04 00 00 00 3f fa
2019-05-13 08:24:50.834 TRACE - dcmnet   - Read PDU HEAD TCP: type: 04, length: 16378 (3ffa)
2019-05-13 08:24:50.834 TRACE - dcmnet   - DUL  FSM Table: State: 6 Event: 9
2019-05-13 08:24:50.834 TRACE - dcmnet   - DUL  Event:  P-DATA-TF PDU (on transport)
2019-05-13 08:24:50.834 TRACE - dcmnet   - DUL  Action: DT 2 Indicate P DATA PDU Received
2019-05-13 08:24:50.927 TRACE - dcmdata  - DcmItem::read() returns error = I/O suspension or premature end of stream
2019-05-13 08:24:50.927 TRACE - dcmdata  - DcmDataset::read() returns error = I/O suspension or premature end of stream
2019-05-13 08:24:50.927 TRACE - dcmnet   - DIMSE receiveDataSetInMemory: 16372 bytes read (last: NO)
2019-05-13 08:24:50.927 TRACE - dcmnet   - Read PDU HEAD TCP: 04 00 00 00 3f fa
2019-05-13 08:24:50.927 TRACE - dcmnet   - Read PDU HEAD TCP: type: 04, length: 16378 (3ffa)
2019-05-13 08:24:50.927 TRACE - dcmnet   - DUL  FSM Table: State: 6 Event: 9
2019-05-13 08:24:50.927 TRACE - dcmnet   - DUL  Event:  P-DATA-TF PDU (on transport)
2019-05-13 08:24:50.927 TRACE - dcmnet   - DUL  Action: DT 2 Indicate P DATA PDU Received
2019-05-13 08:24:51.020 TRACE - dcmdata  - DcmItem::read() returns error = I/O suspension or premature end of stream
2019-05-13 08:24:51.020 TRACE - dcmdata  - DcmDataset::read() returns error = I/O suspension or premature end of stream
2019-05-13 08:24:51.020 TRACE - dcmnet   - DIMSE receiveDataSetInMemory: 16372 bytes read (last: NO)
2019-05-13 08:24:51.020 TRACE - dcmnet   - Read PDU HEAD TCP: 04 00 00 00 3f fa
2019-05-13 08:24:51.020 TRACE - dcmnet   - Read PDU HEAD TCP: type: 04, length: 16378 (3ffa)
2019-05-13 08:24:51.020 TRACE - dcmnet   - DUL  FSM Table: State: 6 Event: 9
2019-05-13 08:24:51.020 TRACE - dcmnet   - DUL  Event:  P-DATA-TF PDU (on transport)
2019-05-13 08:24:51.020 TRACE - dcmnet   - DUL  Action: DT 2 Indicate P DATA PDU Received
2019-05-13 08:24:51.122 TRACE - dcmdata  - DcmItem::read() returns error = I/O suspension or premature end of stream
2019-05-13 08:24:51.122 TRACE - dcmdata  - DcmDataset::read() returns error = I/O suspension or premature end of stream
2019-05-13 08:24:51.122 TRACE - dcmnet   - DIMSE receiveDataSetInMemory: 16372 bytes read (last: NO)
2019-05-13 08:24:51.122 TRACE - dcmnet   - Read PDU HEAD TCP: 04 00 00 00 3f fa
2019-05-13 08:24:51.122 TRACE - dcmnet   - Read PDU HEAD TCP: type: 04, length: 16378 (3ffa)
2019-05-13 08:24:51.122 TRACE - dcmnet   - DUL  FSM Table: State: 6 Event: 9
2019-05-13 08:24:51.122 TRACE - dcmnet   - DUL  Event:  P-DATA-TF PDU (on transport)
2019-05-13 08:24:51.122 TRACE - dcmnet   - DUL  Action: DT 2 Indicate P DATA PDU Received
2019-05-13 08:24:51.214 TRACE - dcmdata  - DcmItem::read() returns error = I/O suspension or premature end of stream
2019-05-13 08:24:51.214 TRACE - dcmdata  - DcmDataset::read() returns error = I/O suspension or premature end of stream
2019-05-13 08:24:51.215 TRACE - dcmnet   - DIMSE receiveDataSetInMemory: 16372 bytes read (last: NO)
2019-05-13 08:24:51.215 TRACE - dcmnet   - Read PDU HEAD TCP: 04 00 00 00 3f fa
2019-05-13 08:24:51.215 TRACE - dcmnet   - Read PDU HEAD TCP: type: 04, length: 16378 (3ffa)
2019-05-13 08:24:51.215 TRACE - dcmnet   - DUL  FSM Table: State: 6 Event: 9
2019-05-13 08:24:51.215 TRACE - dcmnet   - DUL  Event:  P-DATA-TF PDU (on transport)
2019-05-13 08:24:51.215 TRACE - dcmnet   - DUL  Action: DT 2 Indicate P DATA PDU Received
2019-05-13 08:24:51.307 TRACE - dcmdata  - DcmItem::read() returns error = I/O suspension or premature end of stream
2019-05-13 08:24:51.307 TRACE - dcmdata  - DcmDataset::read() returns error = I/O suspension or premature end of stream
2019-05-13 08:24:51.307 TRACE - dcmnet   - DIMSE receiveDataSetInMemory: 16372 bytes read (last: NO)
2019-05-13 08:24:51.307 TRACE - dcmnet   - Read PDU HEAD TCP: 04 00 00 00 3f fa
2019-05-13 08:24:51.307 TRACE - dcmnet   - Read PDU HEAD TCP: type: 04, length: 16378 (3ffa)
2019-05-13 08:24:51.307 TRACE - dcmnet   - DUL  FSM Table: State: 6 Event: 9
2019-05-13 08:24:51.307 TRACE - dcmnet   - DUL  Event:  P-DATA-TF PDU (on transport)
2019-05-13 08:24:51.307 TRACE - dcmnet   - DUL  Action: DT 2 Indicate P DATA PDU Received
2019-05-13 08:24:51.409 TRACE - dcmdata  - DcmItem::read() returns error = I/O suspension or premature end of stream
2019-05-13 08:24:51.409 TRACE - dcmdata  - DcmDataset::read() returns error = I/O suspension or premature end of stream
2019-05-13 08:24:51.409 TRACE - dcmnet   - DIMSE receiveDataSetInMemory: 16372 bytes read (last: NO)
2019-05-13 08:24:51.409 TRACE - dcmnet   - Read PDU HEAD TCP: 04 00 00 00 3f fa
2019-05-13 08:24:51.409 TRACE - dcmnet   - Read PDU HEAD TCP: type: 04, length: 16378 (3ffa)
2019-05-13 08:24:51.409 TRACE - dcmnet   - DUL  FSM Table: State: 6 Event: 9
2019-05-13 08:24:51.409 TRACE - dcmnet   - DUL  Event:  P-DATA-TF PDU (on transport)
2019-05-13 08:24:51.409 TRACE - dcmnet   - DUL  Action: DT 2 Indicate P DATA PDU Received
2019-05-13 08:24:51.502 TRACE - dcmdata  - DcmItem::read() returns error = I/O suspension or premature end of stream
2019-05-13 08:24:51.502 TRACE - dcmdata  - DcmDataset::read() returns error = I/O suspension or premature end of stream
2019-05-13 08:24:51.502 TRACE - dcmnet   - DIMSE receiveDataSetInMemory: 16372 bytes read (last: NO)
2019-05-13 08:24:51.502 TRACE - dcmnet   - Read PDU HEAD TCP: 04 00 00 00 3f fa
2019-05-13 08:24:51.502 TRACE - dcmnet   - Read PDU HEAD TCP: type: 04, length: 16378 (3ffa)
2019-05-13 08:24:51.502 TRACE - dcmnet   - DUL  FSM Table: State: 6 Event: 9
2019-05-13 08:24:51.502 TRACE - dcmnet   - DUL  Event:  P-DATA-TF PDU (on transport)
2019-05-13 08:24:51.502 TRACE - dcmnet   - DUL  Action: DT 2 Indicate P DATA PDU Received
2019-05-13 08:24:51.595 TRACE - dcmdata  - DcmItem::read() returns error = I/O suspension or premature end of stream
2019-05-13 08:24:51.595 TRACE - dcmdata  - DcmDataset::read() returns error = I/O suspension or premature end of stream
2019-05-13 08:24:51.595 TRACE - dcmnet   - DIMSE receiveDataSetInMemory: 16372 bytes read (last: NO)
2019-05-13 08:24:51.595 TRACE - dcmnet   - Read PDU HEAD TCP: 04 00 00 00 3f fa
2019-05-13 08:24:51.595 TRACE - dcmnet   - Read PDU HEAD TCP: type: 04, length: 16378 (3ffa)
2019-05-13 08:24:51.595 TRACE - dcmnet   - DUL  FSM Table: State: 6 Event: 9
2019-05-13 08:24:51.595 TRACE - dcmnet   - DUL  Event:  P-DATA-TF PDU (on transport)
2019-05-13 08:24:51.595 TRACE - dcmnet   - DUL  Action: DT 2 Indicate P DATA PDU Received
2019-05-13 08:24:51.696 TRACE - dcmdata  - DcmItem::read() returns error = I/O suspension or premature end of stream
2019-05-13 08:24:51.696 TRACE - dcmdata  - DcmDataset::read() returns error = I/O suspension or premature end of stream
2019-05-13 08:24:51.696 TRACE - dcmnet   - DIMSE receiveDataSetInMemory: 16372 bytes read (last: NO)
2019-05-13 08:24:51.696 TRACE - dcmnet   - Read PDU HEAD TCP: 04 00 00 00 3f fa
2019-05-13 08:24:51.696 TRACE - dcmnet   - Read PDU HEAD TCP: type: 04, length: 16378 (3ffa)
2019-05-13 08:24:51.696 TRACE - dcmnet   - DUL  FSM Table: State: 6 Event: 9
2019-05-13 08:24:51.696 TRACE - dcmnet   - DUL  Event:  P-DATA-TF PDU (on transport)
2019-05-13 08:24:51.696 TRACE - dcmnet   - DUL  Action: DT 2 Indicate P DATA PDU Received
2019-05-13 08:24:51.789 TRACE - dcmdata  - DcmItem::read() returns error = I/O suspension or premature end of stream
2019-05-13 08:24:51.789 TRACE - dcmdata  - DcmDataset::read() returns error = I/O suspension or premature end of stream
2019-05-13 08:24:51.789 TRACE - dcmnet   - DIMSE receiveDataSetInMemory: 16372 bytes read (last: NO)
2019-05-13 08:24:51.789 TRACE - dcmnet   - Read PDU HEAD TCP: 04 00 00 00 3f fa
2019-05-13 08:24:51.789 TRACE - dcmnet   - Read PDU HEAD TCP: type: 04, length: 16378 (3ffa)
2019-05-13 08:24:51.789 TRACE - dcmnet   - DUL  FSM Table: State: 6 Event: 9
2019-05-13 08:24:51.789 TRACE - dcmnet   - DUL  Event:  P-DATA-TF PDU (on transport)
2019-05-13 08:24:51.789 TRACE - dcmnet   - DUL  Action: DT 2 Indicate P DATA PDU Received
2019-05-13 08:24:51.882 TRACE - dcmdata  - DcmItem::read() returns error = I/O suspension or premature end of stream
2019-05-13 08:24:51.882 TRACE - dcmdata  - DcmDataset::read() returns error = I/O suspension or premature end of stream
2019-05-13 08:24:51.882 TRACE - dcmnet   - DIMSE receiveDataSetInMemory: 16372 bytes read (last: NO)
2019-05-13 08:24:51.882 TRACE - dcmnet   - Read PDU HEAD TCP: 04 00 00 00 3f fa
2019-05-13 08:24:51.882 TRACE - dcmnet   - Read PDU HEAD TCP: type: 04, length: 16378 (3ffa)
2019-05-13 08:24:51.882 TRACE - dcmnet   - DUL  FSM Table: State: 6 Event: 9
2019-05-13 08:24:51.882 TRACE - dcmnet   - DUL  Event:  P-DATA-TF PDU (on transport)
2019-05-13 08:24:51.882 TRACE - dcmnet   - DUL  Action: DT 2 Indicate P DATA PDU Received
2019-05-13 08:24:51.975 TRACE - dcmdata  - DcmItem::read() returns error = I/O suspension or premature end of stream
2019-05-13 08:24:51.975 TRACE - dcmdata  - DcmDataset::read() returns error = I/O suspension or premature end of stream
2019-05-13 08:24:51.975 TRACE - dcmnet   - DIMSE receiveDataSetInMemory: 16372 bytes read (last: NO)
2019-05-13 08:24:51.975 TRACE - dcmnet   - Read PDU HEAD TCP: 04 00 00 00 3f fa
2019-05-13 08:24:51.975 TRACE - dcmnet   - Read PDU HEAD TCP: type: 04, length: 16378 (3ffa)
2019-05-13 08:24:51.975 TRACE - dcmnet   - DUL  FSM Table: State: 6 Event: 9
2019-05-13 08:24:51.975 TRACE - dcmnet   - DUL  Event:  P-DATA-TF PDU (on transport)
2019-05-13 08:24:51.975 TRACE - dcmnet   - DUL  Action: DT 2 Indicate P DATA PDU Received
2019-05-13 08:24:52.077 TRACE - dcmdata  - DcmItem::read() returns error = I/O suspension or premature end of stream
2019-05-13 08:24:52.077 TRACE - dcmdata  - DcmDataset::read() returns error = I/O suspension or premature end of stream
2019-05-13 08:24:52.077 TRACE - dcmnet   - DIMSE receiveDataSetInMemory: 16372 bytes read (last: NO)
2019-05-13 08:24:52.077 TRACE - dcmnet   - Read PDU HEAD TCP: 04 00 00 00 3f fa
2019-05-13 08:24:52.077 TRACE - dcmnet   - Read PDU HEAD TCP: type: 04, length: 16378 (3ffa)
2019-05-13 08:24:52.077 TRACE - dcmnet   - DUL  FSM Table: State: 6 Event: 9
2019-05-13 08:24:52.077 TRACE - dcmnet   - DUL  Event:  P-DATA-TF PDU (on transport)
2019-05-13 08:24:52.077 TRACE - dcmnet   - DUL  Action: DT 2 Indicate P DATA PDU Received
2019-05-13 08:24:52.169 TRACE - dcmdata  - DcmItem::read() returns error = I/O suspension or premature end of stream
2019-05-13 08:24:52.170 TRACE - dcmdata  - DcmDataset::read() returns error = I/O suspension or premature end of stream
2019-05-13 08:24:52.170 TRACE - dcmnet   - DIMSE receiveDataSetInMemory: 16372 bytes read (last: NO)
2019-05-13 08:24:52.170 TRACE - dcmnet   - Read PDU HEAD TCP: 04 00 00 00 3f fa
2019-05-13 08:24:52.170 TRACE - dcmnet   - Read PDU HEAD TCP: type: 04, length: 16378 (3ffa)
2019-05-13 08:24:52.170 TRACE - dcmnet   - DUL  FSM Table: State: 6 Event: 9
2019-05-13 08:24:52.170 TRACE - dcmnet   - DUL  Event:  P-DATA-TF PDU (on transport)
2019-05-13 08:24:52.170 TRACE - dcmnet   - DUL  Action: DT 2 Indicate P DATA PDU Received
2019-05-13 08:24:52.262 TRACE - dcmdata  - DcmItem::read() returns error = I/O suspension or premature end of stream
2019-05-13 08:24:52.262 TRACE - dcmdata  - DcmDataset::read() returns error = I/O suspension or premature end of stream
2019-05-13 08:24:52.263 TRACE - dcmnet   - DIMSE receiveDataSetInMemory: 16372 bytes read (last: NO)
2019-05-13 08:24:52.263 TRACE - dcmnet   - Read PDU HEAD TCP: 04 00 00 00 3f fa
2019-05-13 08:24:52.263 TRACE - dcmnet   - Read PDU HEAD TCP: type: 04, length: 16378 (3ffa)
2019-05-13 08:24:52.263 TRACE - dcmnet   - DUL  FSM Table: State: 6 Event: 9
2019-05-13 08:24:52.263 TRACE - dcmnet   - DUL  Event:  P-DATA-TF PDU (on transport)
2019-05-13 08:24:52.263 TRACE - dcmnet   - DUL  Action: DT 2 Indicate P DATA PDU Received
2019-05-13 08:24:52.364 TRACE - dcmdata  - DcmItem::read() returns error = I/O suspension or premature end of stream
2019-05-13 08:24:52.364 TRACE - dcmdata  - DcmDataset::read() returns error = I/O suspension or premature end of stream
2019-05-13 08:24:52.364 TRACE - dcmnet   - DIMSE receiveDataSetInMemory: 16372 bytes read (last: NO)
2019-05-13 08:24:52.364 TRACE - dcmnet   - Read PDU HEAD TCP: 04 00 00 00 3f fa
2019-05-13 08:24:52.364 TRACE - dcmnet   - Read PDU HEAD TCP: type: 04, length: 16378 (3ffa)
2019-05-13 08:24:52.364 TRACE - dcmnet   - DUL  FSM Table: State: 6 Event: 9
2019-05-13 08:24:52.364 TRACE - dcmnet   - DUL  Event:  P-DATA-TF PDU (on transport)
2019-05-13 08:24:52.364 TRACE - dcmnet   - DUL  Action: DT 2 Indicate P DATA PDU Received
2019-05-13 08:24:52.457 TRACE - dcmdata  - DcmItem::read() returns error = I/O suspension or premature end of stream
2019-05-13 08:24:52.457 TRACE - dcmdata  - DcmDataset::read() returns error = I/O suspension or premature end of stream
2019-05-13 08:24:52.457 TRACE - dcmnet   - DIMSE receiveDataSetInMemory: 16372 bytes read (last: NO)
2019-05-13 08:24:52.457 TRACE - dcmnet   - Read PDU HEAD TCP: 04 00 00 00 3f fa
2019-05-13 08:24:52.457 TRACE - dcmnet   - Read PDU HEAD TCP: type: 04, length: 16378 (3ffa)
2019-05-13 08:24:52.457 TRACE - dcmnet   - DUL  FSM Table: State: 6 Event: 9
2019-05-13 08:24:52.457 TRACE - dcmnet   - DUL  Event:  P-DATA-TF PDU (on transport)
2019-05-13 08:24:52.457 TRACE - dcmnet   - DUL  Action: DT 2 Indicate P DATA PDU Received
2019-05-13 08:24:52.550 TRACE - dcmdata  - DcmItem::read() returns error = I/O suspension or premature end of stream
2019-05-13 08:24:52.550 TRACE - dcmdata  - DcmDataset::read() returns error = I/O suspension or premature end of stream
2019-05-13 08:24:52.550 TRACE - dcmnet   - DIMSE receiveDataSetInMemory: 16372 bytes read (last: NO)
2019-05-13 08:24:52.550 TRACE - dcmnet   - Read PDU HEAD TCP: 04 00 00 00 3f fa
2019-05-13 08:24:52.550 TRACE - dcmnet   - Read PDU HEAD TCP: type: 04, length: 16378 (3ffa)
2019-05-13 08:24:52.550 TRACE - dcmnet   - DUL  FSM Table: State: 6 Event: 9
2019-05-13 08:24:52.550 TRACE - dcmnet   - DUL  Event:  P-DATA-TF PDU (on transport)
2019-05-13 08:24:52.550 TRACE - dcmnet   - DUL  Action: DT 2 Indicate P DATA PDU Received
2019-05-13 08:24:52.651 TRACE - dcmdata  - DcmItem::read() returns error = I/O suspension or premature end of stream
2019-05-13 08:24:52.651 TRACE - dcmdata  - DcmDataset::read() returns error = I/O suspension or premature end of stream
2019-05-13 08:24:52.651 TRACE - dcmnet   - DIMSE receiveDataSetInMemory: 16372 bytes read (last: NO)
2019-05-13 08:24:52.651 TRACE - dcmnet   - Read PDU HEAD TCP: 04 00 00 00 3f fa
2019-05-13 08:24:52.651 TRACE - dcmnet   - Read PDU HEAD TCP: type: 04, length: 16378 (3ffa)
2019-05-13 08:24:52.651 TRACE - dcmnet   - DUL  FSM Table: State: 6 Event: 9
2019-05-13 08:24:52.651 TRACE - dcmnet   - DUL  Event:  P-DATA-TF PDU (on transport)
2019-05-13 08:24:52.651 TRACE - dcmnet   - DUL  Action: DT 2 Indicate P DATA PDU Received
2019-05-13 08:24:52.744 TRACE - dcmdata  - DcmItem::read() returns error = I/O suspension or premature end of stream
2019-05-13 08:24:52.744 TRACE - dcmdata  - DcmDataset::read() returns error = I/O suspension or premature end of stream
2019-05-13 08:24:52.744 TRACE - dcmnet   - DIMSE receiveDataSetInMemory: 16372 bytes read (last: NO)
2019-05-13 08:24:52.744 TRACE - dcmnet   - Read PDU HEAD TCP: 04 00 00 00 3f fa
2019-05-13 08:24:52.744 TRACE - dcmnet   - Read PDU HEAD TCP: type: 04, length: 16378 (3ffa)
2019-05-13 08:24:52.744 TRACE - dcmnet   - DUL  FSM Table: State: 6 Event: 9
2019-05-13 08:24:52.744 TRACE - dcmnet   - DUL  Event:  P-DATA-TF PDU (on transport)
2019-05-13 08:24:52.744 TRACE - dcmnet   - DUL  Action: DT 2 Indicate P DATA PDU Received
2019-05-13 08:24:52.837 TRACE - dcmdata  - DcmItem::read() returns error = I/O suspension or premature end of stream
2019-05-13 08:24:52.837 TRACE - dcmdata  - DcmDataset::read() returns error = I/O suspension or premature end of stream
2019-05-13 08:24:52.837 TRACE - dcmnet   - DIMSE receiveDataSetInMemory: 16372 bytes read (last: NO)
2019-05-13 08:24:52.837 TRACE - dcmnet   - Read PDU HEAD TCP: 04 00 00 00 3f fa
2019-05-13 08:24:52.837 TRACE - dcmnet   - Read PDU HEAD TCP: type: 04, length: 16378 (3ffa)
2019-05-13 08:24:52.837 TRACE - dcmnet   - DUL  FSM Table: State: 6 Event: 9
2019-05-13 08:24:52.837 TRACE - dcmnet   - DUL  Event:  P-DATA-TF PDU (on transport)
2019-05-13 08:24:52.837 TRACE - dcmnet   - DUL  Action: DT 2 Indicate P DATA PDU Received
2019-05-13 08:24:52.939 TRACE - dcmdata  - DcmItem::read() returns error = I/O suspension or premature end of stream
2019-05-13 08:24:52.939 TRACE - dcmdata  - DcmDataset::read() returns error = I/O suspension or premature end of stream
2019-05-13 08:24:52.939 TRACE - dcmnet   - DIMSE receiveDataSetInMemory: 16372 bytes read (last: NO)
2019-05-13 08:24:52.939 TRACE - dcmnet   - Read PDU HEAD TCP: 04 00 00 00 3f fa
2019-05-13 08:24:52.939 TRACE - dcmnet   - Read PDU HEAD TCP: type: 04, length: 16378 (3ffa)
2019-05-13 08:24:52.939 TRACE - dcmnet   - DUL  FSM Table: State: 6 Event: 9
2019-05-13 08:24:52.939 TRACE - dcmnet   - DUL  Event:  P-DATA-TF PDU (on transport)
2019-05-13 08:24:52.939 TRACE - dcmnet   - DUL  Action: DT 2 Indicate P DATA PDU Received
2019-05-13 08:24:53.032 TRACE - dcmdata  - DcmItem::read() returns error = I/O suspension or premature end of stream
2019-05-13 08:24:53.032 TRACE - dcmdata  - DcmDataset::read() returns error = I/O suspension or premature end of stream
2019-05-13 08:24:53.032 TRACE - dcmnet   - DIMSE receiveDataSetInMemory: 16372 bytes read (last: NO)
2019-05-13 08:24:53.032 TRACE - dcmnet   - Read PDU HEAD TCP: 04 00 00 00 3f fa
2019-05-13 08:24:53.032 TRACE - dcmnet   - Read PDU HEAD TCP: type: 04, length: 16378 (3ffa)
2019-05-13 08:24:53.032 TRACE - dcmnet   - DUL  FSM Table: State: 6 Event: 9
2019-05-13 08:24:53.032 TRACE - dcmnet   - DUL  Event:  P-DATA-TF PDU (on transport)
2019-05-13 08:24:53.032 TRACE - dcmnet   - DUL  Action: DT 2 Indicate P DATA PDU Received
2019-05-13 08:24:53.125 TRACE - dcmdata  - DcmItem::read() returns error = I/O suspension or premature end of stream
2019-05-13 08:24:53.125 TRACE - dcmdata  - DcmDataset::read() returns error = I/O suspension or premature end of stream
2019-05-13 08:24:53.125 TRACE - dcmnet   - DIMSE receiveDataSetInMemory: 16372 bytes read (last: NO)
2019-05-13 08:24:53.125 TRACE - dcmnet   - Read PDU HEAD TCP: 04 00 00 00 3f fa
2019-05-13 08:24:53.125 TRACE - dcmnet   - Read PDU HEAD TCP: type: 04, length: 16378 (3ffa)
2019-05-13 08:24:53.125 TRACE - dcmnet   - DUL  FSM Table: State: 6 Event: 9
2019-05-13 08:24:53.125 TRACE - dcmnet   - DUL  Event:  P-DATA-TF PDU (on transport)
2019-05-13 08:24:53.125 TRACE - dcmnet   - DUL  Action: DT 2 Indicate P DATA PDU Received
2019-05-13 08:24:53.226 TRACE - dcmdata  - DcmItem::read() returns error = I/O suspension or premature end of stream
2019-05-13 08:24:53.226 TRACE - dcmdata  - DcmDataset::read() returns error = I/O suspension or premature end of stream
2019-05-13 08:24:53.226 TRACE - dcmnet   - DIMSE receiveDataSetInMemory: 16372 bytes read (last: NO)
2019-05-13 08:24:53.226 TRACE - dcmnet   - Read PDU HEAD TCP: 04 00 00 00 3f fa
2019-05-13 08:24:53.226 TRACE - dcmnet   - Read PDU HEAD TCP: type: 04, length: 16378 (3ffa)
2019-05-13 08:24:53.226 TRACE - dcmnet   - DUL  FSM Table: State: 6 Event: 9
2019-05-13 08:24:53.226 TRACE - dcmnet   - DUL  Event:  P-DATA-TF PDU (on transport)
2019-05-13 08:24:53.226 TRACE - dcmnet   - DUL  Action: DT 2 Indicate P DATA PDU Received
2019-05-13 08:24:53.319 TRACE - dcmdata  - DcmItem::read() returns error = I/O suspension or premature end of stream
2019-05-13 08:24:53.319 TRACE - dcmdata  - DcmDataset::read() returns error = I/O suspension or premature end of stream
2019-05-13 08:24:53.319 TRACE - dcmnet   - DIMSE receiveDataSetInMemory: 16372 bytes read (last: NO)
2019-05-13 08:24:53.319 TRACE - dcmnet   - Read PDU HEAD TCP: 04 00 00 00 3f fa
2019-05-13 08:24:53.319 TRACE - dcmnet   - Read PDU HEAD TCP: type: 04, length: 16378 (3ffa)
2019-05-13 08:24:53.319 TRACE - dcmnet   - DUL  FSM Table: State: 6 Event: 9
2019-05-13 08:24:53.319 TRACE - dcmnet   - DUL  Event:  P-DATA-TF PDU (on transport)
2019-05-13 08:24:53.319 TRACE - dcmnet   - DUL  Action: DT 2 Indicate P DATA PDU Received
2019-05-13 08:24:53.412 TRACE - dcmdata  - DcmItem::read() returns error = I/O suspension or premature end of stream
2019-05-13 08:24:53.412 TRACE - dcmdata  - DcmDataset::read() returns error = I/O suspension or premature end of stream
2019-05-13 08:24:53.412 TRACE - dcmnet   - DIMSE receiveDataSetInMemory: 16372 bytes read (last: NO)
2019-05-13 08:24:53.412 TRACE - dcmnet   - Read PDU HEAD TCP: 04 00 00 00 3f fa
2019-05-13 08:24:53.412 TRACE - dcmnet   - Read PDU HEAD TCP: type: 04, length: 16378 (3ffa)
2019-05-13 08:24:53.412 TRACE - dcmnet   - DUL  FSM Table: State: 6 Event: 9
2019-05-13 08:24:53.412 TRACE - dcmnet   - DUL  Event:  P-DATA-TF PDU (on transport)
2019-05-13 08:24:53.412 TRACE - dcmnet   - DUL  Action: DT 2 Indicate P DATA PDU Received
2019-05-13 08:24:53.513 TRACE - dcmdata  - DcmItem::read() returns error = I/O suspension or premature end of stream
2019-05-13 08:24:53.513 TRACE - dcmdata  - DcmDataset::read() returns error = I/O suspension or premature end of stream
2019-05-13 08:24:53.513 TRACE - dcmnet   - DIMSE receiveDataSetInMemory: 16372 bytes read (last: NO)
2019-05-13 08:24:53.513 TRACE - dcmnet   - Read PDU HEAD TCP: 04 00 00 00 3f fa
2019-05-13 08:24:53.513 TRACE - dcmnet   - Read PDU HEAD TCP: type: 04, length: 16378 (3ffa)
2019-05-13 08:24:53.514 TRACE - dcmnet   - DUL  FSM Table: State: 6 Event: 9
2019-05-13 08:24:53.514 TRACE - dcmnet   - DUL  Event:  P-DATA-TF PDU (on transport)
2019-05-13 08:24:53.514 TRACE - dcmnet   - DUL  Action: DT 2 Indicate P DATA PDU Received
2019-05-13 08:24:53.606 TRACE - dcmdata  - DcmItem::read() returns error = I/O suspension or premature end of stream
2019-05-13 08:24:53.606 TRACE - dcmdata  - DcmDataset::read() returns error = I/O suspension or premature end of stream
2019-05-13 08:24:53.606 TRACE - dcmnet   - DIMSE receiveDataSetInMemory: 16372 bytes read (last: NO)
2019-05-13 08:24:53.606 TRACE - dcmnet   - Read PDU HEAD TCP: 04 00 00 00 3f fa
2019-05-13 08:24:53.606 TRACE - dcmnet   - Read PDU HEAD TCP: type: 04, length: 16378 (3ffa)
2019-05-13 08:24:53.606 TRACE - dcmnet   - DUL  FSM Table: State: 6 Event: 9
2019-05-13 08:24:53.606 TRACE - dcmnet   - DUL  Event:  P-DATA-TF PDU (on transport)
2019-05-13 08:24:53.606 TRACE - dcmnet   - DUL  Action: DT 2 Indicate P DATA PDU Received
2019-05-13 08:24:53.699 TRACE - dcmdata  - DcmItem::read() returns error = I/O suspension or premature end of stream
2019-05-13 08:24:53.699 TRACE - dcmdata  - DcmDataset::read() returns error = I/O suspension or premature end of stream
2019-05-13 08:24:53.699 TRACE - dcmnet   - DIMSE receiveDataSetInMemory: 16372 bytes read (last: NO)
2019-05-13 08:24:53.699 TRACE - dcmnet   - Read PDU HEAD TCP: 04 00 00 00 3f fa
2019-05-13 08:24:53.700 TRACE - dcmnet   - Read PDU HEAD TCP: type: 04, length: 16378 (3ffa)
2019-05-13 08:24:53.700 TRACE - dcmnet   - DUL  FSM Table: State: 6 Event: 9
2019-05-13 08:24:53.700 TRACE - dcmnet   - DUL  Event:  P-DATA-TF PDU (on transport)
2019-05-13 08:24:53.700 TRACE - dcmnet   - DUL  Action: DT 2 Indicate P DATA PDU Received
2019-05-13 08:24:53.792 TRACE - dcmdata  - DcmItem::read() returns error = I/O suspension or premature end of stream
2019-05-13 08:24:53.792 TRACE - dcmdata  - DcmDataset::read() returns error = I/O suspension or premature end of stream
2019-05-13 08:24:53.792 TRACE - dcmnet   - DIMSE receiveDataSetInMemory: 16372 bytes read (last: NO)
2019-05-13 08:24:53.792 TRACE - dcmnet   - Read PDU HEAD TCP: 04 00 00 00 3f fa
2019-05-13 08:24:53.792 TRACE - dcmnet   - Read PDU HEAD TCP: type: 04, length: 16378 (3ffa)
2019-05-13 08:24:53.792 TRACE - dcmnet   - DUL  FSM Table: State: 6 Event: 9
2019-05-13 08:24:53.792 TRACE - dcmnet   - DUL  Event:  P-DATA-TF PDU (on transport)
2019-05-13 08:24:53.792 TRACE - dcmnet   - DUL  Action: DT 2 Indicate P DATA PDU Received
2019-05-13 08:24:53.894 TRACE - dcmdata  - DcmItem::read() returns error = I/O suspension or premature end of stream
2019-05-13 08:24:53.894 TRACE - dcmdata  - DcmDataset::read() returns error = I/O suspension or premature end of stream
2019-05-13 08:24:53.894 TRACE - dcmnet   - DIMSE receiveDataSetInMemory: 16372 bytes read (last: NO)
2019-05-13 08:24:53.894 TRACE - dcmnet   - Read PDU HEAD TCP: 04 00 00 00 3f fa
2019-05-13 08:24:53.894 TRACE - dcmnet   - Read PDU HEAD TCP: type: 04, length: 16378 (3ffa)
2019-05-13 08:24:53.894 TRACE - dcmnet   - DUL  FSM Table: State: 6 Event: 9
2019-05-13 08:24:53.894 TRACE - dcmnet   - DUL  Event:  P-DATA-TF PDU (on transport)
2019-05-13 08:24:53.894 TRACE - dcmnet   - DUL  Action: DT 2 Indicate P DATA PDU Received
2019-05-13 08:24:53.987 TRACE - dcmdata  - DcmItem::read() returns error = I/O suspension or premature end of stream
2019-05-13 08:24:53.987 TRACE - dcmdata  - DcmDataset::read() returns error = I/O suspension or premature end of stream
2019-05-13 08:24:53.987 TRACE - dcmnet   - DIMSE receiveDataSetInMemory: 16372 bytes read (last: NO)
2019-05-13 08:24:53.987 TRACE - dcmnet   - Read PDU HEAD TCP: 04 00 00 00 3f fa
2019-05-13 08:24:53.987 TRACE - dcmnet   - Read PDU HEAD TCP: type: 04, length: 16378 (3ffa)
2019-05-13 08:24:53.987 TRACE - dcmnet   - DUL  FSM Table: State: 6 Event: 9
2019-05-13 08:24:53.987 TRACE - dcmnet   - DUL  Event:  P-DATA-TF PDU (on transport)
2019-05-13 08:24:53.987 TRACE - dcmnet   - DUL  Action: DT 2 Indicate P DATA PDU Received
2019-05-13 08:24:54.080 TRACE - dcmdata  - DcmItem::read() returns error = I/O suspension or premature end of stream
2019-05-13 08:24:54.080 TRACE - dcmdata  - DcmDataset::read() returns error = I/O suspension or premature end of stream
2019-05-13 08:24:54.080 TRACE - dcmnet   - DIMSE receiveDataSetInMemory: 16372 bytes read (last: NO)
2019-05-13 08:24:54.080 TRACE - dcmnet   - Read PDU HEAD TCP: 04 00 00 00 3f fa
2019-05-13 08:24:54.080 TRACE - dcmnet   - Read PDU HEAD TCP: type: 04, length: 16378 (3ffa)
2019-05-13 08:24:54.080 TRACE - dcmnet   - DUL  FSM Table: State: 6 Event: 9
2019-05-13 08:24:54.080 TRACE - dcmnet   - DUL  Event:  P-DATA-TF PDU (on transport)
2019-05-13 08:24:54.080 TRACE - dcmnet   - DUL  Action: DT 2 Indicate P DATA PDU Received
2019-05-13 08:24:54.181 TRACE - dcmdata  - DcmItem::read() returns error = I/O suspension or premature end of stream
2019-05-13 08:24:54.181 TRACE - dcmdata  - DcmDataset::read() returns error = I/O suspension or premature end of stream
2019-05-13 08:24:54.181 TRACE - dcmnet   - DIMSE receiveDataSetInMemory: 16372 bytes read (last: NO)
2019-05-13 08:24:54.181 TRACE - dcmnet   - Read PDU HEAD TCP: 04 00 00 00 3f fa
2019-05-13 08:24:54.181 TRACE - dcmnet   - Read PDU HEAD TCP: type: 04, length: 16378 (3ffa)
2019-05-13 08:24:54.181 TRACE - dcmnet   - DUL  FSM Table: State: 6 Event: 9
2019-05-13 08:24:54.181 TRACE - dcmnet   - DUL  Event:  P-DATA-TF PDU (on transport)
2019-05-13 08:24:54.181 TRACE - dcmnet   - DUL  Action: DT 2 Indicate P DATA PDU Received
2019-05-13 08:24:54.274 TRACE - dcmdata  - DcmItem::read() returns error = I/O suspension or premature end of stream
2019-05-13 08:24:54.274 TRACE - dcmdata  - DcmDataset::read() returns error = I/O suspension or premature end of stream
2019-05-13 08:24:54.274 TRACE - dcmnet   - DIMSE receiveDataSetInMemory: 16372 bytes read (last: NO)
2019-05-13 08:24:54.274 TRACE - dcmnet   - Read PDU HEAD TCP: 04 00 00 00 3f fa
2019-05-13 08:24:54.274 TRACE - dcmnet   - Read PDU HEAD TCP: type: 04, length: 16378 (3ffa)
2019-05-13 08:24:54.274 TRACE - dcmnet   - DUL  FSM Table: State: 6 Event: 9
2019-05-13 08:24:54.274 TRACE - dcmnet   - DUL  Event:  P-DATA-TF PDU (on transport)
2019-05-13 08:24:54.274 TRACE - dcmnet   - DUL  Action: DT 2 Indicate P DATA PDU Received
2019-05-13 08:24:54.367 TRACE - dcmdata  - DcmItem::read() returns error = I/O suspension or premature end of stream
2019-05-13 08:24:54.367 TRACE - dcmdata  - DcmDataset::read() returns error = I/O suspension or premature end of stream
2019-05-13 08:24:54.367 TRACE - dcmnet   - DIMSE receiveDataSetInMemory: 16372 bytes read (last: NO)
2019-05-13 08:24:54.367 TRACE - dcmnet   - Read PDU HEAD TCP: 04 00 00 00 3f fa
2019-05-13 08:24:54.367 TRACE - dcmnet   - Read PDU HEAD TCP: type: 04, length: 16378 (3ffa)
2019-05-13 08:24:54.367 TRACE - dcmnet   - DUL  FSM Table: State: 6 Event: 9
2019-05-13 08:24:54.367 TRACE - dcmnet   - DUL  Event:  P-DATA-TF PDU (on transport)
2019-05-13 08:24:54.367 TRACE - dcmnet   - DUL  Action: DT 2 Indicate P DATA PDU Received
2019-05-13 08:24:54.469 TRACE - dcmdata  - DcmItem::read() returns error = I/O suspension or premature end of stream
2019-05-13 08:24:54.469 TRACE - dcmdata  - DcmDataset::read() returns error = I/O suspension or premature end of stream
2019-05-13 08:24:54.469 TRACE - dcmnet   - DIMSE receiveDataSetInMemory: 16372 bytes read (last: NO)
2019-05-13 08:24:54.469 TRACE - dcmnet   - Read PDU HEAD TCP: 04 00 00 00 3f fa
2019-05-13 08:24:54.469 TRACE - dcmnet   - Read PDU HEAD TCP: type: 04, length: 16378 (3ffa)
2019-05-13 08:24:54.469 TRACE - dcmnet   - DUL  FSM Table: State: 6 Event: 9
2019-05-13 08:24:54.469 TRACE - dcmnet   - DUL  Event:  P-DATA-TF PDU (on transport)
2019-05-13 08:24:54.469 TRACE - dcmnet   - DUL  Action: DT 2 Indicate P DATA PDU Received
2019-05-13 08:24:54.561 TRACE - dcmdata  - DcmItem::read() returns error = I/O suspension or premature end of stream
2019-05-13 08:24:54.561 TRACE - dcmdata  - DcmDataset::read() returns error = I/O suspension or premature end of stream
2019-05-13 08:24:54.561 TRACE - dcmnet   - DIMSE receiveDataSetInMemory: 16372 bytes read (last: NO)
2019-05-13 08:24:54.561 TRACE - dcmnet   - Read PDU HEAD TCP: 04 00 00 00 3f fa
2019-05-13 08:24:54.561 TRACE - dcmnet   - Read PDU HEAD TCP: type: 04, length: 16378 (3ffa)
2019-05-13 08:24:54.561 TRACE - dcmnet   - DUL  FSM Table: State: 6 Event: 9
2019-05-13 08:24:54.561 TRACE - dcmnet   - DUL  Event:  P-DATA-TF PDU (on transport)
2019-05-13 08:24:54.561 TRACE - dcmnet   - DUL  Action: DT 2 Indicate P DATA PDU Received
2019-05-13 08:24:54.654 TRACE - dcmdata  - DcmItem::read() returns error = I/O suspension or premature end of stream
2019-05-13 08:24:54.654 TRACE - dcmdata  - DcmDataset::read() returns error = I/O suspension or premature end of stream
2019-05-13 08:24:54.654 TRACE - dcmnet   - DIMSE receiveDataSetInMemory: 16372 bytes read (last: NO)
2019-05-13 08:24:54.654 TRACE - dcmnet   - Read PDU HEAD TCP: 04 00 00 00 2b 3a
2019-05-13 08:24:54.655 TRACE - dcmnet   - Read PDU HEAD TCP: type: 04, length: 11066 (2b3a)
2019-05-13 08:24:54.655 TRACE - dcmnet   - DUL  FSM Table: State: 6 Event: 9
2019-05-13 08:24:54.655 TRACE - dcmnet   - DUL  Event:  P-DATA-TF PDU (on transport)
2019-05-13 08:24:54.655 TRACE - dcmnet   - DUL  Action: DT 2 Indicate P DATA PDU Received
2019-05-13 08:24:54.722 TRACE - dcmdata  - DcmItem::read() returns error = Normal
2019-05-13 08:24:54.722 TRACE - dcmdata  - DcmItem::searchSubFromHere() Element (7fe0,0010) found
2019-05-13 08:24:54.722 TRACE - dcmdata  - DcmDataset::read() returns error = Normal
2019-05-13 08:24:54.722 TRACE - dcmnet   - DIMSE receiveDataSetInMemory: 11060 bytes read (last: YES)
2019-05-13 08:24:54.722 TRACE - dcmdata  - DcmItem::insert() Element (0000,0000) VR="UL" inserted at beginning
2019-05-13 08:24:54.722 TRACE - dcmdata  - DcmItem::insert() Element (0000,0100) VR="US" inserted
2019-05-13 08:24:54.722 TRACE - dcmdata  - DcmItem::insert() Element (0000,0120) VR="US" inserted
2019-05-13 08:24:54.722 TRACE - dcmdata  - DcmItem::insert() Element (0000,0800) VR="US" inserted
2019-05-13 08:24:54.722 TRACE - dcmdata  - DcmItem::insert() Element (0000,0900) VR="US" inserted
2019-05-13 08:24:54.722 TRACE - dcmdata  - DcmItem::insert() Element (0000,0002) VR="UI" inserted
2019-05-13 08:24:54.722 TRACE - dcmdata  - DcmItem::insert() Element (0000,1000) VR="UI" inserted
2019-05-13 08:24:54.722 TRACE - dcmnet   - DIMSE Command to be sent on Presentation Context ID: 1
2019-05-13 08:24:54.722 TRACE - dcmnet   - DIMSE Command to send:
2019-05-13 08:24:54.722 TRACE - dcmnet   - 
2019-05-13 08:24:54.722 TRACE - dcmnet   - # Dicom-Data-Set
2019-05-13 08:24:54.722 TRACE - dcmnet   - # Used TransferSyntax: Little Endian Explicit
2019-05-13 08:24:54.722 TRACE - dcmnet   - (0000,0000) UL 0                                        #   4, 1 CommandGroupLength
2019-05-13 08:24:54.722 TRACE - dcmnet   - (0000,0002) UI =EnhancedMRImageStorage                  #  28, 1 AffectedSOPClassUID
2019-05-13 08:24:54.722 TRACE - dcmnet   - (0000,0100) US 32769                                    #   2, 1 CommandField
2019-05-13 08:24:54.722 TRACE - dcmnet   - (0000,0120) US 1                                        #   2, 1 MessageIDBeingRespondedTo
2019-05-13 08:24:54.722 TRACE - dcmnet   - (0000,0800) US 257                                      #   2, 1 DataSetType
2019-05-13 08:24:54.722 TRACE - dcmnet   - (0000,0900) US 0                                        #   2, 1 Status
2019-05-13 08:24:54.722 TRACE - dcmnet   - (0000,1000) UI [1.3.46.670589.11.33493.5.20.1.1.9096.2018050109101507058] #  56, 1 AffectedSOPInstanceUID
2019-05-13 08:24:54.722 TRACE - dcmnet   - 
2019-05-13 08:24:54.722 TRACE - dcmnet   - DIMSE sendDcmDataset: sending 152 bytes
2019-05-13 08:24:54.722 TRACE - dcmnet   - DUL  FSM Table: State: 6 Event: 8
2019-05-13 08:24:54.722 TRACE - dcmnet   - DUL  Event:  P-DATA request primitive
2019-05-13 08:24:54.722 TRACE - dcmnet   - DUL  Action: DT 1 Send P DATA PDU
2019-05-13 08:24:54.723 TRACE - dcmnet   - DIMSE receiveCommand
2019-05-13 08:24:55.116 TRACE - dcmnet   - Read PDU HEAD TCP: 05 00 00 00 00 04
2019-05-13 08:24:55.116 TRACE - dcmnet   - Read PDU HEAD TCP: type: 05, length: 4 (04)
2019-05-13 08:24:55.116 TRACE - dcmnet   - DUL  FSM Table: State: 6 Event: 11
2019-05-13 08:24:55.116 TRACE - dcmnet   - DUL  Event:  A-RELEASE-RQ PDU (on transport)
2019-05-13 08:24:55.116 TRACE - dcmnet   - DUL  Action: AR 2 Indicate Release
2019-05-13 08:24:55.116  INFO - storescp - Association Release
2019-05-13 08:24:55.116 TRACE - dcmnet   - DUL  FSM Table: State: 8 Event: 13
2019-05-13 08:24:55.116 TRACE - dcmnet   - DUL  Event:  A-RELEASE response primitive
2019-05-13 08:24:55.116 TRACE - dcmnet   - DUL  Action: AR 4 Send Release RP
2019-05-13 08:25:00.287 TRACE - dcmnet   - Timeout while waiting for incoming network data
2019-05-13 08:25:05.291 TRACE - dcmnet   - Timeout while waiting for incoming network data
2019-05-13 08:25:10.295 TRACE - dcmnet   - Timeout while waiting for incoming network data
2019-05-13 08:25:15.299 TRACE - dcmnet   - Timeout while waiting for incoming network data
This block is the slowest (approx. 1 second for each iteration):

Code: Select all

2019-05-13 08:24:34.479 TRACE - dcmdata  - DcmItem::read() returns error = I/O suspension or premature end of stream
2019-05-13 08:24:34.479 TRACE - dcmdata  - DcmDataset::read() returns error = I/O suspension or premature end of stream
2019-05-13 08:24:34.479 TRACE - dcmnet   - DIMSE receiveDataSetInMemory: 16372 bytes read (last: NO)
2019-05-13 08:24:34.479 TRACE - dcmnet   - Read PDU HEAD TCP: 04 00 00 00 3f fa
2019-05-13 08:24:34.479 TRACE - dcmnet   - Read PDU HEAD TCP: type: 04, length: 16378 (3ffa)
2019-05-13 08:24:34.479 TRACE - dcmnet   - DUL  FSM Table: State: 6 Event: 9
2019-05-13 08:24:34.479 TRACE - dcmnet   - DUL  Event:  P-DATA-TF PDU (on transport)
2019-05-13 08:24:34.479 TRACE - dcmnet   - DUL  Action: DT 2 Indicate P DATA PDU Received
What are those DcmItem::read() returns error = I/O suspension or premature end of stream?, is there a way to speed it up?.

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

Re: storescp much slower than scp (copy through ssh)

#10 Post by J. Riesmeier »

The "I/O suspension or premature end of stream" status code is just the way DCMTK's DICOM dataset parser notifies the caller (in this case, the storage receiver) e.g. that further bytes are needed in order to parse a data element.
This block is the slowest (approx. 1 second for each iteration):
One second for a single PDU of 16K seems to be pretty long, so how fast is your connection between SCU and SCP and how large is your DICOM sample file?

martinrame
Posts: 347
Joined: Mon, 2009-02-23, 19:57

Re: storescp much slower than scp (copy through ssh)

#11 Post by martinrame »

The dicom sample file is 3.4Mb, and the connection is about 1.5mb/s (please take a look at the first post of this thread), copying the file usings scp takes 12seconds against 22 seconds sending the file to storescp using dcmsend.

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

Re: storescp much slower than scp (copy through ssh)

#12 Post by J. Riesmeier »

Now, I checked a similar scenario between a Debian stable (64 bit) and a Mint Linux (64 bit) system over a simple DSL connection. Both dcmsend/storescp (version 3.6.4) and scp transfer a 5 MB DICOM object/file with more or less the same speed. Sometimes even the DICOM C-STORE is a little faster since it does not use any encryption.

Bottom line: I guess that the reason why DICOM C-STORE is much slower on your configuration must the caused by some technical detail in your environment. Maybe, you should use a network analysis tool for further investigation.

martinrame
Posts: 347
Joined: Mon, 2009-02-23, 19:57

Re: storescp much slower than scp (copy through ssh)

#13 Post by martinrame »

Could you execute both operations (dcmsend and scp) preceded by the command "time" to see the global result in seconds?.

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

Re: storescp much slower than scp (copy through ssh)

#14 Post by J. Riesmeier »

I did exactly this.

martinrame
Posts: 347
Joined: Mon, 2009-02-23, 19:57

Re: storescp much slower than scp (copy through ssh)

#15 Post by martinrame »

Weird, because I did a test against two different servers (one Digital Ocean and other Vultr) and both gave very similar results 12 seconds for scp and 22 seconds for dcmsend.

Post Reply

Who is online

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