Investigate performance degradation in reindex of datasets with large numbers of files

[landreev]

This issue is to finish the investigation started in #8097.
Will copy-and-paste relevant experimental data/discussion from the corresponding PR #8152.

The short version of it is that it takes about 6 minutes to directly index a prod. dataset with 25K files ("directly" = via /api/admin/index/dataset), but the time goes up to 6 hours for the same dataset during an async. reindex (via /api/admin/index or /api/admin/index/continue). The difference between the 2 scenarios appears to have to do with where the dataset entity is instantiated in relation to the main transaction. (this is all explained in more details in the comments from #8152 below). This must have some rational explanation, related to how the transaction context is managed by the EJB. There's a good chance the same issue is affecting the performance elsewhere in the code when we have to modify datasets with similar numbers of files.

[landreev]

from #8152:

One extra data point:
(as always, any observations reported need to be verified)
We don't fully understand what's going on. But we have confirmed that the dataset above takes a very long time to index ONLY in the context of index-all. It takes a much more manageable time when indexed on its own directly. (/api/admin/index vs. /api/admin/index/dataset?persistentId=).

However, the difference between the 2 cases above may not have anything to do with how much data in other datasets has been processed by the time index-all gets to this dataset. I.e., the difference in performance appears to be present even when "all" in "index-all" is just this one dataset. The experiment illustrating the point is to have this dataset be the only one in the database with indextime=NULL, then run /api/admin/index/continue. This goes through the same code path as index-all, but only for unindexed datasets.
And the only difference in the code that I'm seeing right away is that indexall/continue is performed asynchronously; AND that it calls indexService.indexDatasetInNewTransaction(). While /api/admin/index/dataset calls indexService.indexDataset().

My gut feeling has always been that whatever was making datasets with too many files unmanageable had something to do with transactions. But we do need something more solid than that.

There were most definitely some algorithmic inefficiencies inside the indexDataset methods (like the comparison methods that have already been looked into). It's not clear however how much that has to do with the awful performance of index-all on datasets like this one. Case in point, the dataset 10.7910/DVN/ZYKVED - it has even more files; but only one version, the draft. Indexing it should not involve any comparisons (?), but it appears to be taking a very long time too. So could it really be a function of the sheer number of child objects being forced into the transaction context? That in turn may also be a function of something about the way we instantiate these objects inside the method.

I'll point out that at the very least we have a workaround for index-all specifically; even if it's bulky. I.e., knowing that datasets like the one above can be indexed in a more manageable way outside of index-all, that's what we could be doing. But we absolutely need to figure out what's going on, since this appears to be the same issue that makes such datasets unmanageable in other ways - takes forever to edit, save, etc.

[landreev]

from #8152:

A followup update:

And the only difference in the code that I'm seeing right away is that indexall/continue is performed asynchronously; AND that it calls indexService.indexDatasetInNewTransaction(). While /api/admin/index/dataset calls indexService.indexDataset().

Actually, there's a 3rd difference, which appears to be the crucial one: indexService.indexDataset() takes a Dataset object as an argument; while indexService.indexDatasetInNewTransaction() takes a Long dataset id and instantiates the dataset inside.

Here's the experiment:

We know that indexing 3CTMKP via /api/admin/index/dataset takes minutes in the develop branch. This is the API code:

@GET
@Path("dataset")
public Response indexDatasetByPersistentId(@QueryParam("persistentId") String persistentId) {
     ...
     Future<String> indexDatasetFuture = indexService.indexDataset(dataset, doNormalSolrDocCleanUp);    

It appears that all it takes to make it take hours instead is to change the last line to

     Future<String> indexDatasetFuture = indexService.indexDatasetInNewTransaction(dataset.getId());

So we are omitting the @Asynchronous code in IndexBatchServiceBean that index-all calls; as it does not appear to play a role in the performance degradation.
The fact that indexDatasetInNewTransaction() has the @TransactionAttribute(REQUIRES_NEW) attribute and indexDataset() doesn't should NOT be making any difference in this scenario. Because the API bean Index.java is not an EJB, so the method indexDatasetByPersistentId() does not have a transaction context of its own. Meaning a new transaction is created when it calls either of the two IndexServiceBean methods above, regardless of the transaction attributes there. (Does this make sense? Is it actually correct?)

So... it appears that what makes the crucial difference is whether the dataset entity is instantiated within, or outside of the working transaction. This must be some known and documented EJB behavior at play. So, stackoverflow is our friend?

(I tested the above; but, as always, do not take my word for it necessarily)

[landreev]

from #8152:

And another followup:
The reason we pass the id of the dataset to indexDatasetInNewTransaction() - we made that change on purpose (I did, in 2018), to address a memory leak-like behavior: before it was made, the dataset was instantiated in the top-level method in IndexBatchServiceBean - but that apparently was resulting in something being kept in memory, and growing significantly, until the end of index-all. Which of course takes a very long time.
I'm expecting that it should be possible to go back to passing a dataset entity; and still be able to clear everything from memory right away. But I also really want to find out for sure why instantiating inside the transaction is so expensive time-wise.

In the "slow" mode, under index-all/continue, it appears that the first pass, through the draft version, still happens fairly quickly. And then it is the second pass, through the published version, that slows down to a crawl. Which is consistent with what Steve observed earlier when trying to instantiate the published filemetadatas from scratch inside the indexing method.

[donsizemore]

The short version of it is that it takes about 6 minutes to directly index a prod. dataset with 25K files ("directly" = via /api/admin/index/dataset), but the time goes up to 6 hours for the same dataset during an async. reindex (via /api/admin/index or /api/admin/index/continue). The difference between the 2 scenarios appears to have to do with where the dataset entity is instantiated in relation to the main transaction. (this is all explained in more details in the comments from #8152 below).

This is interesting to me, as UNC Dataverse has always had 22 datasets which fail during an asynchronous index but succeed individually. I've kept a little shell script for them each time we need to re-index.

[landreev]

from #8152:

a query count I saved earlier:
This from indexing this "big dataset" directly, (/api/admin/index/dataset), testing with the develop branch (takes 6.5 minutes); 300K+ queries:

  50631 SELECT t0.ID, t0.DTYPE, t0.AUTHORITY, t0.CREATEDATE, t0.GLOBALIDCREATETIME, t0.IDENTIFIER, t0.IDENTIFIERREGISTERED, t0.INDEXTIME, t0.MODIFICATIONTIME, t0.PERMISSIONINDEXTIME, t0.PERMISSIONMODIFICATIONTIME, t0.PREVIEWIMAGEAVAILABLE, t0.PROTOCOL, t0.PUBLICATIONDATE, t0.STORAGEIDENTIFIER, t0.CREATOR_ID, t0.OWNER_ID, t0.RELEASEUSER_ID, t1.ID, t1.AFFILIATION, t1.ALIAS, t1.DATAVERSETYPE, t1.description, t1.EXTERNALLABELSETNAME, t1.FACETROOT, t1.GUESTBOOKROOT, t1.METADATABLOCKROOT, t1.METADATALANGUAGE, t1.NAME, t1.PERMISSIONROOT, t1.STORAGEDRIVER, t1.TEMPLATEROOT, t1.THEMEROOT, t1.DEFAULTCONTRIBUTORROLE_ID, t1.DEFAULTTEMPLATE_ID FROM DVOBJECT t0, DATAVERSE t1
  50620 SELECT t0.ID, t0.NAME, t0.DATASET_ID FROM DATAFILECATEGORY t0, FILEMETADATA_DATAFILECATEGORY t1
  50620 SELECT ID, INTERVIEWINSTRUCTION, ISWEIGHTVAR, LABEL, LITERALQUESTION, NOTES, POSTQUESTION, UNIVERSE, WEIGHTED, DATAVARIABLE_ID, FILEMETADATA_ID, WEIGHTVARIABLE_ID FROM VARIABLEMETADATA
  25322 SELECT ID, CONTENT, LANG, NAME FROM SETTING
  25313 SELECT t0.ID, t0.DTYPE, t0.AUTHORITY, t0.CREATEDATE, t0.GLOBALIDCREATETIME, t0.IDENTIFIER, t0.IDENTIFIERREGISTERED, t0.INDEXTIME, t0.MODIFICATIONTIME, t0.PERMISSIONINDEXTIME, t0.PERMISSIONMODIFICATIONTIME, t0.PREVIEWIMAGEAVAILABLE, t0.PROTOCOL, t0.PUBLICATIONDATE, t0.STORAGEIDENTIFIER, t0.CREATOR_ID, t0.OWNER_ID, t0.RELEASEUSER_ID, t1.ID, t1.EXTERNALLABELSETNAME, t1.FILEACCESSREQUEST, t1.HARVESTIDENTIFIER, t1.LASTEXPORTTIME, t1.METADATALANGUAGE, t1.STORAGEDRIVER, t1.USEGENERICTHUMBNAIL, t1.citationDateDatasetFieldType_id, t1.harvestingClient_id, t1.guestbook_id, t1.thumbnailfile_id FROM DVOBJECT t0, DATASET t1
  25312 SELECT t0.ID, t0.DTYPE, t0.AUTHORITY, t0.CREATEDATE, t0.GLOBALIDCREATETIME, t0.IDENTIFIER, t0.IDENTIFIERREGISTERED, t0.INDEXTIME, t0.MODIFICATIONTIME, t0.PERMISSIONINDEXTIME, t0.PERMISSIONMODIFICATIONTIME, t0.PREVIEWIMAGEAVAILABLE, t0.PROTOCOL, t0.PUBLICATIONDATE, t0.STORAGEIDENTIFIER, t0.CREATOR_ID, t0.OWNER_ID, t0.RELEASEUSER_ID, t1.ID, t1.CHECKSUMTYPE, t1.CHECKSUMVALUE, t1.CONTENTTYPE, t1.FILESIZE, t1.INGESTSTATUS, t1.PREVIOUSDATAFILEID, t1.prov_entityname, t1.RESTRICTED, t1.ROOTDATAFILEID FROM DVOBJECT t0, DATAFILE t1
  25312 SELECT ID, DESCRIPTION, DIRECTORYLABEL, LABEL, prov_freeform, RESTRICTED, VERSION, DATAFILE_ID, DATASETVERSION_ID FROM FILEMETADATA
  25311 SELECT ID, CONTROLCARD, FORCETYPECHECK, LABELSFILE, TEXTENCODING, datafile_id FROM INGESTREQUEST
  25310 SELECT ID, CASEQUANTITY, ORIGINALFILEFORMAT, ORIGINALFILENAME, ORIGINALFILESIZE, ORIGINALFORMATVERSION, RECORDSPERCASE, UNF, VARQUANTITY, DATAFILE_ID FROM DATATABLE
     38 SELECT ID, DISPLAYORDER, value, DATASETFIELD_ID FROM DATASETFIELDVALUE
     25 SELECT ID, ADVANCEDSEARCHFIELDTYPE, ALLOWCONTROLLEDVOCABULARY, ALLOWMULTIPLES, description, DISPLAYFORMAT, DISPLAYONCREATE, DISPLAYORDER, FACETABLE, FIELDTYPE, name, REQUIRED, title, uri, VALIDATIONFORMAT, WATERMARK, METADATABLOCK_ID, PARENTDATASETFIELDTYPE_ID FROM DATASETFIELDTYPE
     22 SELECT t1.ID, t1.DISPLAYORDER, t1.IDENTIFIER, t1.STRVALUE, t1.DATASETFIELDTYPE_ID FROM DATASETFIELD_CONTROLLEDVOCABULARYVALUE t0, CONTROLLEDVOCABULARYVALUE t1
     16 SELECT ID, DATASETFIELDTYPE_ID, DATASETVERSION_ID, PARENTDATASETFIELDCOMPOUNDVALUE_ID, TEMPLATE_ID FROM DATASETFIELD
     10 SELECT ID, DISPLAYORDER, PARENTDATASETFIELD_ID FROM DATASETFIELDCOMPOUNDVALUE
      8 SELECT ID, AFFILIATION, CREATEDTIME, DEACTIVATED, DEACTIVATEDTIME, EMAIL, EMAILCONFIRMED, FIRSTNAME, LASTAPIUSETIME, LASTLOGINTIME, LASTNAME, POSITION, SUPERUSER, USERIDENTIFIER FROM AUTHENTICATEDUSER
      5 SELECT ID, DISPLAYORDER, IDENTIFIER, STRVALUE, DATASETFIELDTYPE_ID FROM CONTROLLEDVOCABULARYVALUE
      4 SELECT ID, AUTHENTICATIONPROVIDERID, PERSISTENTUSERID, AUTHENTICATEDUSER_ID FROM AUTHENTICATEDUSERLOOKUP
      4 SELECT ID, ASSIGNEEIDENTIFIER, PRIVATEURLANONYMIZEDACCESS, PRIVATEURLTOKEN, DEFINITIONPOINT_ID, ROLE_ID FROM ROLEASSIGNMENT
      4 SELECT ID, ALIAS, DESCRIPTION, NAME, PERMISSIONBITS, OWNER_ID FROM DATAVERSEROLE
      3 SELECT ID, UNF, ARCHIVALCOPYLOCATION, ARCHIVENOTE, ARCHIVETIME, CREATETIME, DEACCESSIONLINK, EXTERNALSTATUSLABEL, LASTUPDATETIME, MINORVERSIONNUMBER, RELEASETIME, VERSION, VERSIONNOTE, VERSIONNUMBER, VERSIONSTATE, DATASET_ID, termsOfUseAndAccess_id FROM DATASETVERSION
      3 SELECT DISTINCT DTYPE FROM DVOBJECT
      2 SELECT ID, LINKCREATETIME, DATASET_ID, LINKINGDATAVERSE_ID FROM DATASETLINKINGDATAVERSE
      2 SELECT ID, CREATETIME, NAME, USAGECOUNT, DATAVERSE_ID, termsOfUseAndAccess_id FROM TEMPLATE
      2 SELECT ID, BACKGROUNDCOLOR, LINKCOLOR, LINKURL, LOGO, LOGOALIGNMENT, LOGOBACKGROUNDCOLOR, LOGOFOOTER, LOGOFOOTERALIGNMENT, LOGOFOOTERBACKGROUNDCOLOR, LOGOFORMAT, TAGLINE, TEXTCOLOR, dataverse_id FROM DATAVERSETHEME
      2 SELECT ID, AVAILABILITYSTATUS, CITATIONREQUIREMENTS, CONDITIONS, CONFIDENTIALITYDECLARATION, CONTACTFORACCESS, DATAACCESSPLACE, DEPOSITORREQUIREMENTS, DISCLAIMER, FILEACCESSREQUEST, LICENSE, ORIGINALARCHIVE, RESTRICTIONS, SIZEOFCOLLECTION, SPECIALPERMISSIONS, STUDYCOMPLETION, TERMSOFACCESS, TERMSOFUSE FROM TERMSOFUSEANDACCESS
      1 UPDATE DVOBJECT SET PERMISSIONINDEXTIME = '2021-10-18 23:22:04.473'
      1 UPDATE DVOBJECT SET INDEXTIME = '2021-10-18 23:21:37.701'
      1 UPDATE DVOBJECT SET INDEXTIME = '2021-10-18 23:19:11.66'
      1 SELECT t.typlen FROM pg_catalog.pg_type t, pg_catalog.pg_namespace n
      1 SELECT t1.ID, t1.ADVANCEDSEARCHFIELDTYPE, t1.ALLOWCONTROLLEDVOCABULARY, t1.ALLOWMULTIPLES, t1.description, t1.DISPLAYFORMAT, t1.DISPLAYONCREATE, t1.DISPLAYORDER, t1.FACETABLE, t1.FIELDTYPE, t1.name, t1.REQUIRED, t1.title, t1.uri, t1.VALIDATIONFORMAT, t1.WATERMARK, t1.METADATABLOCK_ID, t1.PARENTDATASETFIELDTYPE_ID FROM dataverse_citationDatasetFieldTypes t0, DATASETFIELDTYPE t1
      1 SELECT ID, INFO, REASON, STARTTIME, DATASET_ID, USER_ID FROM DATASETLOCK
      1 SELECT ID, DISPLAYNAME, NAME, namespaceuri, owner_id FROM METADATABLOCK

(some of this is kind of crazy - like the 50K dataverse lookups... that said, it didn't look like the number of queries was going up much when it went to 6.5 hours under index-all... in other words, it was looking like it was not the number of queries that makes it slower; the queries are largely the same, but everything somehow takes longer. so... "something to do with transactions" again. My main interest in this issue would be to find out why this is happening)

[landreev]

from #8152, on the results of the perf. cluster reindex run, with the reordering change implemented in that PR:

A full re-reindex has completed on the perf. cluster without failures and took 45+ hours.

  index all took 164443729 milliseconds|#]
  7466 dataverses and 155387 datasets indexed. index all took 164443729 milliseconds. Solr index was not cleared before indexing.

Important numbers/observations:
Of the total of 155,387 datasets, 155,000 were reindexed in 18 hours. (that roughly translates into all the datasets with less than 500 files).
~140,000 datasets with 10 or less files were reindexed in ~13 hours.
This confirms that to the users of an installation that needs to erase and rebuild their index from scratch, the search catalog would appear to be repopulated much sooner. This is also a big step up when it comes to being able to search for the most recent datasets, that under the old scheme were not reindexed until the very end of the ordeal.

The last 10 datasets took 21+ hours to index; almost 1/2 of the total time spent.
The evil 25K file dataset (3CTMKP) took the same 6 hours. This is an important data point, confirming what was observed earlier: individual datasets take the same time to index in the context of indexAll/continue, whether it's just 1 dataset on the stack, or if it's being processed after most of the other datasets in the db have been indexed.

3CTMKP is no longer the champion. ZYKVED (44+K files) takes 11 hours.

The sheer number of files does NOT translate into time. It appears that it's only super expensive when there's a draft version that needs to be indexed. GZSBVP has 33+K files, has one published version - and takes minutes to process. It doesn't appear to matter whether 1, or 2 versions need to be indexed. Unlike 3CTMKP, ZYKVED only has a draft.

The time ratio between 3CTMKP and ZYKVED appears to be largely linear to the number of files.

I still support merging the PR for the sake of the reordering change alone. (If nothing else, we can say to the user that we are delivering exactly what he requested). But all of the above, plus all the other useful experiments and research from this PR, need to be copy-and-pasted into a new issue that will be dedicated to investigating the root cause behind the performance degradation first. I also need to archive the Postgres logs and indexing times for individual datasets. So I will be doing that. Plus I want to add a few words to the release note.

[landreev]

@donsizemore Interesting! I now realize you mentioned this before, but I failed to grasp that it was an outright failure only in async. reindex, but not in direct.

[qqmyers]

More thoughts: https://docs.google.com/document/d/1rYAfYqQ_7HeIheo3TiM9VnFfBB43ovZlSWjuKkV7Uuk/edit?usp=sharing