Investigate/diagnose the apparent slowdown between 6.8 and 6.9

[landreev]

As recorded in #11880, there was an observed slowdown between 6.8 and 6.9, at least for the (very few/limited) tests that we measure carefully side-by-side. The results have since been confirmed by rerunning some of the tests, including the full reindexing. It is likely that the degradation is not going to be noticeable for most of the instances, except for the few very large ones like ours. But I need to figure this out before I deploy here at IQSS. (debated whether to open the issue in the local prod. queue instead).

[landreev]

Status update:
As noted elsewhere, there's no "universal slowdown" across the entire application; just a bit of a coincidence that a number of things introduced in different parts of the application happened to affect the few tests that we measure side by side.

1. One test (a full reindex) where the ~30% slowdown was unambiguously observed and measured was traced to a specific PR. Jim and I have been discussing it; a proposed experimental fix or a version thereof may or may not make it into the initial 6.9 deployment patch at HDV. I'm not considering it a hard blocker at this point.
2. The Locust tests appear to have been heavily influenced by the new /compareSummary API test. It was added to dataverse_perf.py relatively recently by Steven. 6.9 was the first release for which this test was included in the benchmark. The test is an order of magnitude+ slower/more expensive than the other tests there so the changes in its performance (discussed below) disproportionately change the behavior of the overall test suite. I went to the trouble to re-run the "classic" Kevin's test batch without it for the 200 and 250 user runs. There is an observable, but less dramatic slowdown at 250 users (and no failures). There is some evidence that it comes from the dataset page performance on datasets with more files. The queries counts are identical between 6.8 and 6.9 however, as was reported earlier in Release 6.9: Conduct performance testing #11880. TBD, but not treating this as a hard blocker either.
3. The /compareSummary API was heavily re-worked in 6.9. Performance-wise, there's no slowdown per se when tested on an idle system. If nothing else, it appears to have been sped up by a hair (~17 sec. vs 18+ sec. for the control dataset doi:10.7910/DVN/29236 with 1577 files in it). The number of database queries issued is essentially identical between the 2 versions. However, something in the 6.9 implementation makes it much more likely to start failing on a busy system. As can be seen in the results recorded for Release 6.9: Conduct performance testing #11880, there were multiple failures on this test for the 200 and 250 users runs on 6.9-RC (with the failure rate utterly abysmal for 250). All the failures were timeouts (the way the API works, all content is generated and delivered at once. 17 sec. in the example above means you have to wait that long to see any bytes). Which likely means in reality that those were not real fatal failures, i.e., if the Locust client were told to wait longer, they would eventually succeed (can/will retest). With the query counts being the same, the culprit is likely memory (?). I'm going to open a dedicated issue for this. I'm debating whether it is worth to investigate the precise reason for this change any further though. I do feel like we probably want to reimplement this API anyway, since I don't think 18 sec. for this is acceptable even if it does not crash the Locust test. For this control dataset, you wait for 17-18 sec. just to get 1KB of data (the actual changes between the 3 versions are minimal). It clearly spends most of this time crawling through the ~1.5K of files. I strongly suspect that it can be reimplemented w/ custom queries, and it should be easy-ish to determine that the files are for the most part identical between the versions.

[landreev]

P.S.

All the failures were timeouts (the way the API works, all content is generated and delivered at once. 17 sec. in the example above means you have to wait that long to see any bytes).

Looking further at the /compareSummary entries in the recorded 6.8 and 6.9-RC results, it can be deduced that it was in fact the result of a 60 sec. timeout:

Also, note that there were identical timeout failures on this test under 6.8 and 250 users as well. But the failure rate went from awful (75 out of 334 = 22%) to abysmal (189 out of 298 = 63%) under 6.9.

[landreev]

Per item 3. above opened #12102.

[landreev]

Closing summary for the issue:
Two dev. efforts were spawned as a result of this investigation:

1. Improve Permission Indexing Performance #12082 - already merged - that has addressed the indexing slowdown and further improved the bulk permissions-only reindexing of a large collection, on top of the gains made in QDR: Multiple transactions for permission reindexing #11822. Some extra testing was performed to collect more data for future development. I'm adding this to the 6.9 patch being deployed in prod. at HDV. I may reach out to other known instances with large databases (such as Borealis) and offer a patch to them.
2. Refactor/optimize the /compareSummary API #12102 - opened a dev. issue. Not something catastrophic or urgent to address, but I am interested in trying to make a pr as I suspect that significant improvements can be made there, for datasets with giant lists of files.

Aside from that, I spent (way) more effort on comparative side by side testing of v6.8 vs v6.9 using our "classic" Locust jobs. Including looking at the memory/GC stats, via jstat etc. on a system under a heavy request load. The only reportable result though is that our locust tests are still of somewhat questionable value, even after all the effort spent on running them under as identical conditions as possible. Somehow there is still enough randomness there that no 2 tests, even when performed under the same database, Dataverse version etc. ever produce identical results, even with the very high numbers of user sessions/rate of requests (where you'd expect things to average themselves based on sheer numbers). If you look at the results from re-running dataverse_perf_classic.py under 200 and 250 "users", it would appear that 6.9 is a bit slower than 6.8. However, the differences are well within the variations you see from re-running each of the tests under the same version repeatedly.

The graph below shows memory utilization and apparent GC passes on the instance overloaded by a 250 "users" locust bombardment. It appears to show that under 6.9 a larger portion of the 10 min. run was spent under a 100% oldgen memory utilization. But in terms of the numbers of requests served and the mean and avg. times per request, the results of the 2 tests were essentially identical. So, it's not clear at all how to interpret this (?).

A simple conclusion is that these locusts tests in their current form, while not entirely useless (they would detect a catastrophic slowdown in one of the pages), are not really worth the time and effort it takes to run them. Especially considering the fact that they are testing a microscopic fraction of the functionality of the application.

A further step would be to run one of the tests, extract the exact requests record from the access log per each of the 250 unique jsession ids and then script it as to repeat that sequence 1:1 each time... But the real takeaway here should be that we just need some better/more sophisticated way to stress test going forward.