Transfer status check times out ("Deadline exceeded: 30.0")

[slifty]

Expected behaviour
Calls to /transfers/status should not fail, and synchronous tasks to getUnitStatuses should not fail even in an instance with millions of Jobs

Current behaviour
When loading /transfers/status the call fails after around 30 seconds. We did some debugging and found that things time out when running the call to getUnitStatuses.

Looking into https://github.com/artefactual/archivematica/blob/42b7dfa46026d78dd16e41504c6aa5a41cb4dd33/src/archivematica/MCPServer/server/rpc_server.py#L336-L415 we see that there is a query:

SELECT SIPUUID,
               MAX(UNIX_TIMESTAMP(createdTime) + createdTimeDec) AS timestamp
            FROM Jobs
            WHERE unitType=%s AND NOT SIPUUID LIKE '%%None%%'
            GROUP BY SIPUUID;

When we run this query manually we see that it takes over a minute, which suggests it is likely at least one culprit of the timeout.

Steps to reproduce

Since this is related to a database state I imagine this is hard to explicitly reproduce. We have around 3 million Jobs in our system.

Your environment (version of Archivematica, operating system, other relevant details)

We're using Archivematica 1.17

Here's the output of EXPLAIN

+---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
| EXPLAIN                                                                                                                                                                                                                                                                                                                                                                                                                                                             |
+---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
| -> Group aggregate: max((unix_timestamp(Jobs.createdTime) + Jobs.createdTimeDec))  (cost=392147 rows=43406) (actual time=3.96..65252 rows=20258 loops=1)
    -> Filter: ((Jobs.unitType = 'unitTransfer') and (not((Jobs.SIPUUID like '%%None%%'))))  (cost=368046 rows=241017) (actual time=2.16..64626 rows=971805 loops=1)
        -> Index scan on Jobs using Jobs_SIPUUID_246989a2  (cost=368046 rows=2.71e+6) (actual time=2.15..63944 rows=3.02e+6 loops=1)
 |
+---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
1 row in set (1 min 5.27 sec)

---

For Artefactual use:

Before you close this issue, you must check off the following:

• All pull requests related to this issue are properly linked
• All pull requests related to this issue have been merged
• A testing plan for this issue has been implemented and passed (testing plan information should be included in the issue body or comments)
• Documentation regarding this issue has been written and merged (if applicable)
• Details about this issue have been added to the release notes (if applicable)

[slifty]

One issue is that the MAX(UNIX_TIMESTAMP(createdTime) + createdTimeDec) AS timestamp line in particular was forcing every candidate row to have this calculation run against it.

There was also no unitType index, which means the unitType condition required a scan.

We fixed this locally by adding an index:

CREATE INDEX Jobs_unitType_SIPUUID_createdTime_createdTimeDec_idx ON Jobs (unitType, SIPUUID, createdTime, createdTimeDec);

(thank you to @liam-lloyd for the above index!)

With this change the 60 second call completes in 1.3 seconds, (which is still pretty expensive for something that is run every 10 seconds, but at least the data loads!)

We also would recommend Remove the AND NOT SIPUUID LIKE '%%None%%' from this query -- it forces every candidate row to be scanned and string-compared. We don't know the reason None would be in a UUID, but if it would be possible to accomplish the same goal by using a static string or a null that would prevent string comparisons in a where clause.

Making both of these changes brings the query down to .88 seconds on our table. This ideally would be under .5 -- possibly this could be accomplished using an additional filter in the WHERE to minimize the number of rows being grouped.

---

With the faster query we no longer have a timeout, but the GET /transfers/status call still takes 19 seconds. We're continuing to investigate, it's likely related to the rest of the logic in getUnitStatus, as each row returned is processed, and the query returns over 20,000 records.

[slifty]

Regarding the "19 seconds" issue, we did more digging and are happy to share some conclusions:

The _units_statuses_handler loads all possible rows in this query (in our case, this is 20,000 rows). It then proceeds to load each Transfer (this is 20,000 queries), and inspects the hidden attribute to filter those out before loading associated Jobs.

There is one low-hanging-fruit improvement here:

1. The hidden filter should happen in the initial query, not after running n queries to load the Transfer objects. This might require a case statement to run the more efficient filter based on the type of unit being loaded (i.e. Transfer vs SIP) but that is an appropriate tradeoff.

There are also a few harder-to-solve issues that still warrant consideration:

2. Having n queries to load Transfers after all filters is still a lot of queries <-- (aka the n+1 problem). Ideally there would be a single query that returns all relevant items.

3. Having an additional n queries to load related Jobs after loading Transfers is an additional n+1 problem. Similar to the previous point ideally the ORM could load a joined object.

Finally...

The only reason the above fixes would solve our problem is that we have been "deleting" Jobs that are older than 24h (thus they are marked as hidden). The reason we do this is that the dashboard / transfer status lacks support for pagination and would be attempting to load all 200k Transfers in our system.

[sarah-mason]

Hi @slifty - as you have a fix, we would welcome the PR. However, this specific function isn't currently covered by tests, so could you include tests in the fix? I understand if that will add additional work. If you have questions, I'll invite you to the development meetings so you can come talk to us. Thank you!

[jens-st]

Hi @slifty, might this issue be related to this observation (#1668)?
We noticed status information requests fail (HTTP 400), both on transfer/status and ingest/status API endpoints and had to implement waits & retries.