Hi,
I have a reasonably large Orthanc instance, running Orthanc 1.2.0 from Docker, with a postgresql database and filesystem storage.
I'm observing pathological behaviour when I send C-Find queries that match everything, even though "LimitFindInstances" and "LimitFindResults" are set to a small value. The issue is also reproducible with the default SQLite backend.
GET /statistics:
{
• "CountInstances": 689307,
• "CountPatients": 57819,
• "CountSeries": 158414,
• "CountStudies": 130246,
• "TotalDiskSize": "116047984033",
• "TotalDiskSizeMB": 110671,
• "TotalUncompressedSize": "198180592865",
• "TotalUncompressedSizeMB": 188999
}
This Query will fail with a timeout for me:
$ findscu -k 0008,0052=PATIENT -k PatientID -k PatientName="*" -P localhost 10406 -v -aet findscu
Server logs:
I1213 21:11:51.216785 CommandDispatcher.cpp:490] Association Received from AET findscu on IP 127.0.0.1
I1213 21:11:51.217917 CommandDispatcher.cpp:688] Association Acknowledged (Max Send PDV: 16372)
I1213 21:11:51.253794 main.cpp:122] Maximum 100 results for C-FIND queries at the Patient, Study and Series levels
I1213 21:11:51.254575 main.cpp:132] Maximum 100 instances will be returned for C-FIND queries at the Instance level
I1213 21:11:51.255086 OrthancFindRequestHandler.cpp:573] DICOM C-Find request at level: Patient
I1213 21:11:51.255351 OrthancFindRequestHandler.cpp:579] (0008,0052) QueryRetrieveLevel = PATIENT
I1213 21:11:51.255738 OrthancFindRequestHandler.cpp:579] (0010,0010) PatientName = *
I1213 21:11:51.256130 OrthancFindRequestHandler.cpp:579] (0010,0020) PatientID =
// (B) note: a long time is spent here. after 60 seconds the client times out and closes the connection (but processing continues)
// With `--trace` this would print "Calling service 5001 from plugin /usr/share/orthanc/plugins/libOrthancPostgreSQLIndex.so"
// lots of times for every patient in the database.
I1213 21:15:11.573283 OrthancFindRequestHandler.cpp:650] Number of candidate resources after fast DB filtering: 57819
I1213 21:15:11.584128 FilesystemStorage.cpp:154] Reading attachment "2a9ff57f-045f-4faa-8c35-71a1d1097dab" of "JSON summary of DICOM" content type
I1213 21:15:11.589036 FilesystemStorage.cpp:154] Reading attachment "7016f596-fcf2-4182-b841-3ce80acbb8dc" of "JSON summary of DICOM" content type
I1213 21:15:11.623047 FilesystemStorage.cpp:154] Reading attachment "1330c169-5bbd-4fdc-b56f-c30a7958c6c2" of "JSON summary of DICOM" content type
I1213 21:15:11.627246 FilesystemStorage.cpp:154] Reading attachment "60610edc-e48b-4089-877a-ee938ffaf7a5" of "JSON summary of DICOM" content type
I1213 21:15:11.632554 FilesystemStorage.cpp:154] Reading attachment "e787c6f3-5f6b-4a49-ac03-315342059088" of "JSON summary of DICOM" content type
// (cut 90 lines)
I1213 21:15:15.548823 FilesystemStorage.cpp:154] Reading attachment "b3b861d9-fcf3-45e1-815f-2a22c5725fd3" of "JSON summary of DICOM" content type
I1213 21:15:15.557923 FilesystemStorage.cpp:154] Reading attachment "f0892161-eef4-4784-a0b6-7beb4094a1c1" of "JSON summary of DICOM" content type
I1213 21:15:15.579617 FilesystemStorage.cpp:154] Reading attachment "f24a6a3d-7300-410b-a11b-dd6a66ca098d" of "JSON summary of DICOM" content type
I1213 21:15:15.595326 FilesystemStorage.cpp:154] Reading attachment "d48a09f9-e029-406f-bc4c-ad7ac0623830" of "JSON summary of DICOM" content type
I1213 21:15:15.600866 FilesystemStorage.cpp:154] Reading attachment "14db3361-4a5b-4b98-8484-1b8f658bbe20" of "JSON summary of DICOM" content type
I1213 21:15:15.603151 OrthancFindRequestHandler.cpp:676] Number of matching resources: 100
E1213 21:15:15.702364 FindScp.cpp:325] Find SCP Failed: DIMSE Failed to send message
0006:031d TCP I/O Error (Broken pipe) occurred in routine: writeDataPDU
// note: this is expected, the client has closed the connection during (B)
I1213 21:15:15.703621 CommandDispatcher.cpp:891] Peer aborted Association (or never connected)
I1213 21:15:15.703764 CommandDispatcher.cpp:903] Association Aborted
Three Observations:
- In this case the result limits are set to a maximum of 100 items. It seems like Orthanc should abort earlier so that it never lands in a situation where it needs looks at more than 100 matches in detail.
- The "Fast DB filtering" seems to set off thousands of tiny SQL Queries in a loop. (with the SQLite Backend these queries are logged as
T1213 23:03:20.025506 Statement.cpp:144] SQLite::Statement::Step SELECT d.id FROM DicomIdentifiers AS d, Resources AS r WHERE d.id = r.internalId AND r.resourceType=? AND d.tagGroup=? AND d.tagElement=? AND d.value GLOB ?
(I've not yet figured out a good way to acquire SQL query logs from the dockerized postgresql instance unfortunately)
- When the client times out after 60 seconds, Orthanc nevertheless continues handling the request instead of aborting the processing. The effect of this is that multiple requests will compound, making the problem worse.
Thank you for reading,
--Levin