Profile and optimize the Registry

[Ostrzyciel]

I did a 5-minute recording the Registry loading nanopubs during the LOAD_FULL phase.

CPU time:

Wall clock time:

Memory allocations:

• I also added a simple loading speed-o-meter. In large batches (>100 nps) I saw loading speeds around 50–80 np/s.
• I saw a lot of "Already listed" messages. In the flame graph, I see that they are coming from a hot path. I don't fully understand the loading logic, but if there is a way to avoid loading duplicates, it would improve performance by a lot.
• The total CPU time that we can influence is 20135 ms.
• Very little influence:
  • Jelly parsing takes 455+125=680 ms. Further optimizations here are unlikely to influence the loading performance.
  • Constructing NanopubImpl takes 825 ms.
  • Reserializing the nanopub in Jelly for the DB takes 360 ms.
• In general, there is a lot of back-and-forth between the Registry and the DB. This adds up to a lot of overhead in sockets and kernel. If we could merge some of these calls together, it would greatly improve performance.
• In a few places, we first check if something exists in Mongo, and then do some operation. Mongo generally discourages such patterns, preferring that you instead use atomic operations (like upserts) that do it all in one call. For example:
  • Here we first check if any invalidations exist, and then re-run the same query to actually get the invalidations. Also, the parsing from TriG a few lines below could be swiched over to Jelly.
  • Here we could combine the has and insert into one operation.
  • Here we could probably combine two selects into one.
• has, getMaxValue, and getMaxValueDocument are very slow, possibly because they are returning more data from the DB than they have to. They should be limited to one result at most.

Recommendations

I could dig deeper into this, but the issues I've found are pretty obvious, and I think should be fixed first.

• [1] Where possible, merge multiple Mongo operations into one.
• [2] Optimize read queries to lower their overhead (has, getMaxValue, and getMaxValueDocument)

[tkuhn]

Great overview, thanks!

I also wanted to look into the reason for the "Already listed" messages, but haven't managed yet. Probably just some lazy coding on my side.

Feel free to go ahead and implement your recommendations.

[Ostrzyciel]

After implementing the changes in #58, the wall clock time plot looks like this:

The vast majority of time is spent waiting on insert / update operations. Because the CPU time of this 300s period is only 14s, anything we optimize in the code, won't have a huge impact on the loading speed.

I think that the easiest way to fix this would be to do these inserts/updates in parallel. Mongo does have a reactive Java driver – we could use that instead, but it would probably require a lot of code rewriting across the entire codebase. I'm not entirely sure how big of an effort that would be. An alternative would be to use a thread pool with the synchronous driver, like in Nanopub Query. That should be a simpler, but less "recommended" way of doing things.

I could look into that further, but I'm not sure how high is all this on the priority list.