[BUG] Memory leak in kitodo:reindex CLI job

[stweil]

Description

Running the reindex jobs works with a small number of documents or very much memory, but fails with out of memory for huge collections. While the job is running, the used memory continuously grows. 10 GB of memory is not sufficient for less than 3000 documents.

Reproduction

Just run the CLI job and watch how the memory usage grows.

Expected Behavior

There is no reason why the required memory should grow with the number of indexed documents.
As soon as a document was indexed, there is no longer a need to store its metadata in RAM.

Environment

• Debian bullseye
• MariaDB 10.5.21
• TYPO3 10
• PHP 7.4.33
• code based on Kitodo.Presentation 5.0.0-rc1

Additional Context

See also issue #822. The fix added there obviously no longer works.

[sebastian-meyer]

Previously all document instances were kept in AbstractDocument::$registry and the AbstractDocument::clearRegistry() method reset that property, in turn freeing up the memory.

As it seems, this property isn't used any more (at least it isn't populated in AbstractDocument::getInstance()) and so AbstractDocument::clearRegistry() has no effect. Instead the document instances are saved using the TYPO3 caching framework (see AbstractDocument::setDocumentCache()).

So my guess would be that AbstractDocument::clearRegistry() needs to clear the document cache instead of resetting the $registry property in order to make it work again.

(And maybe we should rename it to "clearCache()" as well and remove the unused property $registry while we are at it...)

[stweil]

Thanks. If you have a code snippet, we can test that tomorrow.

[sebastian-meyer]

I provided a pull request in #1168. Thanks for reviewing/testing!

[stweil]

I cherry-picked the 2nd commit (1a2ea0d) from that pull request. Indexing still leaks:

Reindex a collection into database and Solr.
============================================

2024-02-04 22:17:20 Indexing 1/2098 with UID "33" ("https://digi.bib.uni-mannheim.de/vl/ubmadesb/oai:digi.bib.uni-mannheim.de:51284.xml") on PID 3 and Solr core 11.
Mem Usage 1: 72380368
Mem Usage 2: 72380368
Mem Usage 3: 76825352
Mem Usage 4: 78123680
Mem Usage 5: 78123552
2024-02-04 22:17:21 Indexing 2/2098 with UID "72" ("https://digi.bib.uni-mannheim.de/fileadmin/digi/416971342/416971342.xml") on PID 3 and Solr core 11.
Mem Usage 1: 78373504
Mem Usage 2: 78373504
Mem Usage 3: 79069448
Mem Usage 4: 80282000
Mem Usage 5: 80282000
[...]
2024-02-04 22:20:58 Indexing 17/2098 with UID "90" ("https://digi.bib.uni-mannheim.de/fileadmin/digi/418980381/418980381_anchor.xml") on PID 3 and Solr core 11.
Mem Usage 1: 124659560
Mem Usage 2: 124659560
Mem Usage 3: 124690384
Mem Usage 4: 124707624
Mem Usage 5: 124707624

The memory traces were produced using this patch:

diff --git a/Classes/Command/ReindexCommand.php b/Classes/Command/ReindexCommand.php
index bcb2da4c..6bb101d6 100644
--- a/Classes/Command/ReindexCommand.php
+++ b/Classes/Command/ReindexCommand.php
@@ -175,14 +175,19 @@ class ReindexCommand extends BaseCommand
                 if ($io->isVerbose()) {
                     $io->writeln(date('Y-m-d H:i:s') . ' Indexing ' . ($id + 1) . '/' . count($documents) . ' with UID "' . $document->getUid() . '" ("' . $document->getLocation() . '") on PID ' . $this->storagePid . ' and Solr core ' . $solrCoreUid . '.');
                 }
+                $io->writeln("Mem Usage 1: ". memory_get_usage());
                 $document->setCurrentDocument($doc);
+                $io->writeln("Mem Usage 2: ". memory_get_usage());
                 // save to database
                 $this->saveToDatabase($document);
+                $io->writeln("Mem Usage 3: ". memory_get_usage());
                 // add to index
                 Indexer::add($document, $this->documentRepository);
             }
+            $io->writeln("Mem Usage 4: ". memory_get_usage());
             // Clear document cache to prevent memory exhaustion.
             AbstractDocument::clearDocumentCache();
+            $io->writeln("Mem Usage 5: ". memory_get_usage());
         }
 
         $io->success('All done!');

[jmechnich]

@sebastian-meyer I have noticed a registry array in Solr/Solr.php. Is it possible that it replaced the functionality of AbstractDocument::$registry (and should be cleared in a similar fashion)?

[sebastian-meyer]

@sebastian-meyer I have noticed a registry array in Solr/Solr.php. Is it possible that it replaced the functionality of AbstractDocument::$registry (and should be cleared in a similar fashion)?

This one actually holds the core-specific instances of the Solr connection objects. That's fine and should not blow up memory usage, since all indexing uses the same connection instance (i. e. there should be only one instance kept by this property during indexing).

But I found another potential memory leak in BaseCommand::saveToDatabase(), where the TYPO3 / Doctrine DBAL persistence manager is continuously populated with documents but never cleared. I've added a PersistenceManager::clearState() command - let's see if this helps! (See the newest commit.)

[beatrycze-volk]

Short update on this topic.

I have looked into this memory usage:

        foreach ($documents as $id => $document) {
            $doc = AbstractDocument::getInstance($document->getLocation(), ['storagePid' => $this->storagePid], true);

            if ($doc === null) {
                $io->warning('WARNING: Document "' . $document->getLocation() . '" could not be loaded. Skip to next document.');
                continue;
            }

            if ($dryRun) {
                $io->writeln('DRY RUN: Would index ' . ($id + 1) . '/' . count($documents) . ' with UID "' . $document->getUid() . '" ("' . $document->getLocation() . '") on PID ' . $this->storagePid . ' and Solr core ' . $solrCoreUid . '.');
            } else {
                if ($io->isVerbose()) {
                    $io->writeln(date('Y-m-d H:i:s') . ' Indexing ' . ($id + 1) . '/' . count($documents) . ' with UID "' . $document->getUid() . '" ("' . $document->getLocation() . '") on PID ' . $this->storagePid . ' and Solr core ' . $solrCoreUid . '.');
                }
                $io->writeln('Peak usage - begin: ' . round(memory_get_peak_usage() / 1024) . ' KB');
                $io->writeln('--------------------------------------------------');
                $io->writeln('Current usage 1: ' . round(memory_get_usage() / 1024) . ' KB');
                $document->setCurrentDocument($doc);
                $io->writeln('Current usage 2: ' . round(memory_get_usage() / 1024) . ' KB - after setCurrentDocument()');
                // save to database
                $this->saveToDatabase($document, $io);
                $io->writeln('Current usage 3: ' . round(memory_get_usage() / 1024) . ' KB - after saveToDatabase()');
                // add to index
                Indexer::add($document, $this->documentRepository);
                $io->writeln('Current usage 4: ' . round(memory_get_usage() / 1024) . ' KB - after add()');
            }
            // Clear document and persistence cache to prevent memory exhaustion.
            AbstractDocument::clearDocumentCache();
            $io->writeln('Current usage 5: ' . round(memory_get_usage() / 1024) . ' KB - after clearDocumentCache()');
            $this->persistenceManager->clearState();
            $io->writeln('Current usage 6: ' . round(memory_get_usage() / 1024) . ' KB - after clearState()');
            $io->writeln('--------------------------------------------------');
            $io->writeln('Peak usage - end: ' . round(memory_get_peak_usage() / 1024) . ' KB');
        }

Results:

2024-05-08 16:13:14 Indexing 1/4320 with UID "2" ("https://digital.slub-dresden.de/data/kitodo/10Kepi_476251419/10Kepi_476251419_mets.xml") on PID 2 and Solr core 1.
Peak usage - begin: 96421 KB
--------------------------------------------------
Current usage 1: 95976 KB
Current usage 2: 95976 KB - after setCurrentDocument()
Current usage 3: 97118 KB - after saveToDatabase()
Current usage 4: 97796 KB - after add()
Current usage 5: 97796 KB - after clearDocumentCache()
Current usage 6: 88742 KB - after clearState()
--------------------------------------------------
Peak usage - end: 97918 KB

2024-05-08 16:13:17 Indexing 2/4320 with UID "3" ("https://digital.slub-dresden.de/data/kitodo/ZachPoet_477896448_0006/ZachPoet_477896448_0006_anchor.xml") on PID 2 and Solr core 1.
Peak usage - begin: 97918 KB
--------------------------------------------------
Current usage 1: 88758 KB
Current usage 2: 88758 KB - after setCurrentDocument()
Current usage 3: 88834 KB - after saveToDatabase()
Current usage 4: 89011 KB - after add()
Current usage 5: 89011 KB - after clearDocumentCache()
Current usage 6: 88998 KB - after clearState()
--------------------------------------------------
Peak usage - end: 97918 KB

2024-05-08 16:13:18 Indexing 3/4320 with UID "4" ("https://digital.slub-dresden.de/data/kitodo/ZachPoet_477887139_0001/ZachPoet_477887139_0001_mets.xml") on PID 2 and Solr core 1.
Peak usage - begin: 97918 KB
--------------------------------------------------
Current usage 1: 89998 KB
Current usage 2: 89998 KB - after setCurrentDocument()
Current usage 3: 92457 KB - after saveToDatabase()
Current usage 4: 96028 KB - after add()
Current usage 5: 96028 KB - after clearDocumentCache()
Current usage 6: 96010 KB - after clearState()
--------------------------------------------------
Peak usage - end: 97918 KB

2024-05-08 16:15:53 Indexing 4/4320 with UID "5" ("https://digital.slub-dresden.de/data/kitodo/6Saso_476248086/6Saso_476248086_mets.xml") on PID 2 and Solr core 1.
Peak usage - begin: 97918 KB
--------------------------------------------------
Current usage 1: 96067 KB
Current usage 2: 96067 KB - after setCurrentDocument()
Current usage 3: 96240 KB - after saveToDatabase()
Current usage 4: 96346 KB - after add()
Current usage 5: 96346 KB - after clearDocumentCache()
Current usage 6: 96332 KB - after clearState()
--------------------------------------------------
Peak usage - end: 97918 KB

.....

2024-05-08 16:44:07 Indexing 700/4320 with UID "701" ("https://digital.slub-dresden.de/data/kitodo/EdelWns_476250269/EdelWns_476250269_mets.xml") on PID 2 and Solr core 1.
Peak usage - begin: 501309 KB
--------------------------------------------------
Current usage 1: 501044 KB
Current usage 2: 501044 KB - after setCurrentDocument()
Current usage 3: 501322 KB - after saveToDatabase()
Current usage 4: 501447 KB - after add()
Current usage 5: 501447 KB - after clearDocumentCache()
Current usage 6: 501433 KB - after clearState()
--------------------------------------------------
Peak usage - end: 501561 KB

2024-05-08 16:44:08 Indexing 701/4320 with UID "702" ("https://digital.slub-dresden.de/data/kitodo/Dankduald_476250048/Dankduald_476250048_mets.xml") on PID 2 and Solr core 1.
Peak usage - begin: 501619 KB
--------------------------------------------------
Current usage 1: 501485 KB
Current usage 2: 501485 KB - after setCurrentDocument()
Current usage 3: 501649 KB - after saveToDatabase()
Current usage 4: 501737 KB - after add()
Current usage 5: 501737 KB - after clearDocumentCache()
Current usage 6: 501723 KB - after clearState()
--------------------------------------------------
Peak usage - end: 501849 KB
2024-05-08 16:44:08 Indexing 702/4320 with UID "703" ("https://digital.slub-dresden.de/data/kitodo/DalaAdol_476247772/DalaAdol_476247772_mets.xml") on PID 2 and Solr core 1.
Peak usage - begin: 501957 KB
--------------------------------------------------
Current usage 1: 501788 KB
Current usage 2: 501788 KB - after setCurrentDocument()
Current usage 3: 501990 KB - after saveToDatabase()
Current usage 4: 502068 KB - after add()
Current usage 5: 502068 KB - after clearDocumentCache()
Current usage 6: 502054 KB - after clearState()
--------------------------------------------------
Peak usage - end: 502180 KB

2024-05-08 16:44:09 Indexing 703/4320 with UID "704" ("https://digital.slub-dresden.de/data/kitodo/CordColl_477887651/CordColl_477887651_mets.xml") on PID 2 and Solr core 1.
Peak usage - begin: 502224 KB
--------------------------------------------------
Current usage 1: 502102 KB
Current usage 2: 502102 KB - after setCurrentDocument()
Current usage 3: 502260 KB - after saveToDatabase()
Current usage 4: 502310 KB - after add()
Current usage 5: 502310 KB - after clearDocumentCache()
Current usage 6: 502296 KB - after clearState()
--------------------------------------------------
Peak usage - end: 502421 KB

....

2024-05-08 17:23:04 Indexing 1505/4320 with UID "1506" ("https://digital.slub-dresden.de/data/kitodo/DresKr_880547324-1922102801_01-v/DresKr_880547324-1922102801_01-v_mets.xml") on PID 2 and Solr core 1.
Peak usage - begin: 892923 KB
--------------------------------------------------
Current usage 1: 892816 KB
Current usage 2: 892816 KB - after setCurrentDocument()
Current usage 3: 893143 KB - after saveToDatabase()
Current usage 4: 893252 KB - after add()
Current usage 5: 893252 KB - after clearDocumentCache()
Current usage 6: 893224 KB - after clearState()
--------------------------------------------------
Peak usage - end: 893339 KB

So basically setCurrentDocument() and clearDocumentCache() have no effect on memory usage.

saveToDatabase() increase it 120-300 KB for single document and around 1 MB if also parent document is included.
add() increase it 50-150 KB and around 3,5 MB if also parent document is included.

clearState() frees around 14 KB for single document and 18 KB for document with the parent.

By this we can calculate that every single document adds between 200 and 400 KB. The main offender is saveToDatabase() but not persistence manager itself as freeing it reduces usage about 5 to 10% of the memory added by this function.

I'm currently analyzing which parts of saveToDatabase() are responsible for this.

In the moment when indexer has passed 1500 documents memory usage is around 872 MB so not even close to the case presented in the #822. There it is already around 5GB. Please correct me if I have have mistaken something.

Changes can be previewed here: https://github.com/kitodo/kitodo-presentation/compare/master...beatrycze-volk:memory?expand=1

[beatrycze-volk]

UPDATE

Results BaseCommand->saveToDatabase():

2024-05-13 12:33:49 Indexing 1/4320 with UID "2" ("https://digital.slub-dresden.de/data/kitodo/10Kepi_476251419/10Kepi_476251419_mets.xml") on PID 2 and Solr core 1.
Peak usage - begin: 96421 KB
------------------------------------------------------
Current usage 1: 95976 KB - before saveToDatabase()
Document uid: 2
saveToDatabase() usage 1-1: 95976 KB - before setCurrentDocument()
saveToDatabase() usage 1-2: 95976 KB - before getToplevelMetadata()
saveToDatabase() usage 1-3: 96361 KB - after getToplevelMetadata()
saveToDatabase() usage 1-4: 96752 KB - before getParentDocumentUidForSaving()
saveToDatabase() usage 1-5: 96754 KB - before persistAll()
saveToDatabase() usage 1-6: 97136 KB - after persistAll()
Current usage 2: 97118 KB - between saveToDatabase() and add()
Current usage 3: 97796 KB - after add()
Current usage 4: 88742 KB - after clearState()
------------------------------------------------------
Peak usage - end: 97918 KB
2024-05-13 12:33:56 Indexing 2/4320 with UID "3" ("https://digital.slub-dresden.de/data/kitodo/ZachPoet_477896448_0006/ZachPoet_477896448_0006_anchor.xml") on PID 2 and Solr core 1.
Peak usage - begin: 97918 KB
------------------------------------------------------
Current usage 1: 88758 KB - before saveToDatabase()
Document uid: 3
saveToDatabase() usage 1-1: 88758 KB - before setCurrentDocument()
saveToDatabase() usage 1-2: 88788 KB - before getToplevelMetadata()
saveToDatabase() usage 1-3: 88806 KB - after getToplevelMetadata()
saveToDatabase() usage 1-4: 88847 KB - before getParentDocumentUidForSaving()
saveToDatabase() usage 1-5: 88849 KB - before persistAll()
saveToDatabase() usage 1-6: 88849 KB - after persistAll()
Current usage 2: 88834 KB - between saveToDatabase() and add()
Current usage 3: 89011 KB - after add()
Current usage 4: 88998 KB - after clearState()
------------------------------------------------------
Peak usage - end: 97918 KB
2024-05-13 12:33:56 Indexing 3/4320 with UID "4" ("https://digital.slub-dresden.de/data/kitodo/ZachPoet_477887139_0001/ZachPoet_477887139_0001_mets.xml") on PID 2 and Solr core 1.
Peak usage - begin: 97918 KB
------------------------------------------------------
Current usage 1: 89998 KB - before saveToDatabase()
Document uid: 4
saveToDatabase() usage 1-1: 89998 KB - before setCurrentDocument()
saveToDatabase() usage 1-2: 90028 KB - before getToplevelMetadata()
saveToDatabase() usage 1-3: 92354 KB - after getToplevelMetadata()
saveToDatabase() usage 1-4: 92396 KB - before getParentDocumentUidForSaving()
Document parent uid: 4
Document uid: 3
saveToDatabase() usage 1-1: 92439 KB - before setCurrentDocument()
saveToDatabase() usage 1-2: 92439 KB - before getToplevelMetadata()
saveToDatabase() usage 1-3: 92457 KB - after getToplevelMetadata()
saveToDatabase() usage 1-4: 92484 KB - before getParentDocumentUidForSaving()
saveToDatabase() usage 1-5: 92485 KB - before persistAll()
saveToDatabase() usage 1-6: 92487 KB - after persistAll()
saveToDatabase() usage 1-5: 92474 KB - before persistAll()
saveToDatabase() usage 1-6: 92476 KB - after persistAll()
Current usage 2: 92457 KB - between saveToDatabase() and add()
Current usage 3: 96068 KB - after add()
Current usage 4: 96050 KB - after clearState()
------------------------------------------------------
Peak usage - end: 97918 KB
2024-05-13 12:36:11 Indexing 4/4320 with UID "5" ("https://digital.slub-dresden.de/data/kitodo/6Saso_476248086/6Saso_476248086_mets.xml") on PID 2 and Solr core 1.
Peak usage - begin: 97918 KB
------------------------------------------------------
Current usage 1: 96107 KB - before saveToDatabase()
Document uid: 5
saveToDatabase() usage 1-1: 96107 KB - before setCurrentDocument()
saveToDatabase() usage 1-2: 96136 KB - before getToplevelMetadata()
saveToDatabase() usage 1-3: 96254 KB - after getToplevelMetadata()
saveToDatabase() usage 1-4: 96295 KB - before getParentDocumentUidForSaving()
saveToDatabase() usage 1-5: 96296 KB - before persistAll()
saveToDatabase() usage 1-6: 96298 KB - after persistAll()
Current usage 2: 96280 KB - between saveToDatabase() and add()
Current usage 3: 96386 KB - after add()
Current usage 4: 96372 KB - after clearState()
------------------------------------------------------
Peak usage - end: 97918 KB
2024-05-13 12:36:12 Indexing 5/4320 with UID "6" ("https://digital.slub-dresden.de/data/kitodo/5PiG_476250676/5PiG_476250676_mets.xml") on PID 2 and Solr core 1.
Peak usage - begin: 97918 KB
------------------------------------------------------
Current usage 1: 96425 KB - before saveToDatabase()
Document uid: 6
saveToDatabase() usage 1-1: 96425 KB - before setCurrentDocument()
saveToDatabase() usage 1-2: 96454 KB - before getToplevelMetadata()
saveToDatabase() usage 1-3: 96568 KB - after getToplevelMetadata()
saveToDatabase() usage 1-4: 96609 KB - before getParentDocumentUidForSaving()
saveToDatabase() usage 1-5: 96610 KB - before persistAll()
saveToDatabase() usage 1-6: 96612 KB - after persistAll()
Current usage 2: 96594 KB - between saveToDatabase() and add()
Current usage 3: 96726 KB - after add()
Current usage 4: 96712 KB - after clearState()
------------------------------------------------------
Peak usage - end: 97918 KB

....

2024-05-13 12:46:24 Indexing 354/4320 with UID "355" ("https://digital.slub-dresden.de/data/kitodo/BchIhm_476250706/BchIhm_476250706_mets.xml") on PID 2 and Solr core 1.
Peak usage - begin: 309513 KB
------------------------------------------------------
Current usage 1: 309068 KB - before saveToDatabase()
Document uid: 355
saveToDatabase() usage 1-1: 309068 KB - before setCurrentDocument()
saveToDatabase() usage 1-2: 309098 KB - before getToplevelMetadata()
saveToDatabase() usage 1-3: 309490 KB - after getToplevelMetadata()
saveToDatabase() usage 1-4: 309531 KB - before getParentDocumentUidForSaving()
saveToDatabase() usage 1-5: 309533 KB - before persistAll()
saveToDatabase() usage 1-6: 309535 KB - after persistAll()
Current usage 2: 309516 KB - between saveToDatabase() and add()
Current usage 3: 309747 KB - after add()
Current usage 4: 309733 KB - after clearState()
------------------------------------------------------
Peak usage - end: 309867 KB
2024-05-13 12:46:25 Indexing 355/4320 with UID "356" ("https://digital.slub-dresden.de/data/kitodo/BegrGo_476250447/BegrGo_476250447_mets.xml") on PID 2 and Solr core 1.
Peak usage - begin: 310159 KB
------------------------------------------------------
Current usage 1: 309846 KB - before saveToDatabase()
Document uid: 356
saveToDatabase() usage 1-1: 309846 KB - before setCurrentDocument()
saveToDatabase() usage 1-2: 309876 KB - before getToplevelMetadata()
saveToDatabase() usage 1-3: 310144 KB - after getToplevelMetadata()
saveToDatabase() usage 1-4: 310185 KB - before getParentDocumentUidForSaving()
saveToDatabase() usage 1-5: 310187 KB - before persistAll()
saveToDatabase() usage 1-6: 310188 KB - after persistAll()
Current usage 2: 310170 KB - between saveToDatabase() and add()
Current usage 3: 310366 KB - after add()
Current usage 4: 310352 KB - after clearState()
------------------------------------------------------
Peak usage - end: 310484 KB
2024-05-13 12:46:25 Indexing 356/4320 with UID "357" ("https://digital.slub-dresden.de/data/kitodo/GssIst_476247438/GssIst_476247438_mets.xml") on PID 2 and Solr core 1.
Peak usage - begin: 310506 KB
------------------------------------------------------
Current usage 1: 310397 KB - before saveToDatabase()
Document uid: 357
saveToDatabase() usage 1-1: 310397 KB - before setCurrentDocument()
saveToDatabase() usage 1-2: 310427 KB - before getToplevelMetadata()
saveToDatabase() usage 1-3: 310516 KB - after getToplevelMetadata()
saveToDatabase() usage 1-4: 310557 KB - before getParentDocumentUidForSaving()
saveToDatabase() usage 1-5: 310559 KB - before persistAll()
saveToDatabase() usage 1-6: 310561 KB - after persistAll()
Current usage 2: 310542 KB - between saveToDatabase() and add()
Current usage 3: 310651 KB - after add()
Current usage 4: 310637 KB - after clearState()
------------------------------------------------------
Peak usage - end: 310815 KB
2024-05-13 12:46:26 Indexing 357/4320 with UID "358" ("https://digital.slub-dresden.de/data/kitodo/AnhaDie_476246342/AnhaDie_476246342_mets.xml") on PID 2 and Solr core 1.
Peak usage - begin: 310815 KB
------------------------------------------------------
Current usage 1: 310682 KB - before saveToDatabase()
Document uid: 358
saveToDatabase() usage 1-1: 310682 KB - before setCurrentDocument()
saveToDatabase() usage 1-2: 310712 KB - before getToplevelMetadata()
saveToDatabase() usage 1-3: 310800 KB - after getToplevelMetadata()
saveToDatabase() usage 1-4: 310841 KB - before getParentDocumentUidForSaving()
saveToDatabase() usage 1-5: 310843 KB - before persistAll()
saveToDatabase() usage 1-6: 310844 KB - after persistAll()
Current usage 2: 310826 KB - between saveToDatabase() and add()
Current usage 3: 310894 KB - after add()
Current usage 4: 310880 KB - after clearState()
------------------------------------------------------
Peak usage - end: 311006 KB
2024-05-13 12:46:27 Indexing 358/4320 with UID "359" ("https://digital.slub-dresden.de/data/kitodo/GrelMass_476248485/GrelMass_476248485_mets.xml") on PID 2 and Solr core 1.
Peak usage - begin: 311006 KB
------------------------------------------------------
Current usage 1: 310908 KB - before saveToDatabase()
Document uid: 359
saveToDatabase() usage 1-1: 310908 KB - before setCurrentDocument()
saveToDatabase() usage 1-2: 310938 KB - before getToplevelMetadata()
saveToDatabase() usage 1-3: 310982 KB - after getToplevelMetadata()
saveToDatabase() usage 1-4: 311023 KB - before getParentDocumentUidForSaving()
saveToDatabase() usage 1-5: 311025 KB - before persistAll()
saveToDatabase() usage 1-6: 311027 KB - after persistAll()
Current usage 2: 311008 KB - between saveToDatabase() and add()
Current usage 3: 311057 KB - after add()
Current usage 4: 311043 KB - after clearState()
------------------------------------------------------
Peak usage - end: 311169 KB

The part which is increasing the memory usage is the function AbstractDocument::getToplevelMetadata(). For some reason clearing the AbstractDocument from cache (AbstractDocument::clearDocumentCache()) doesn't bring any result. Even if it should free anything related to document instance.

Results Indexer::add():

2024-05-13 13:06:40 Indexing 4/4320 with UID "5" ("https://digital.slub-dresden.de/data/kitodo/6Saso_476248086/6Saso_476248086_mets.xml") on PID 2 and Solr core 1.
Peak usage - begin: 97918 KB
------------------------------------------------------
Current usage 1: 96115 KB - before saveToDatabase()
Current usage 2: 96288 KB - between saveToDatabase() and add()
add() usage 2-1: 96288 KB - before self::$processedDocs check
add() usage 2-2: 96288 KB - after solr connect
add() usage 2-5: 96288 KB - before document save
add() usage 2-6: 96289 KB - after document save
add() usage 2-7: 96395 KB - after processLogical()
add() usage 2-8: 96395 KB - after processPhysical()
add() usage 2-9: 96395 KB - after update()
Current usage 3: 96394 KB - after add()
Current usage 4: 96380 KB - after clearState()
------------------------------------------------------
Peak usage - end: 97918 KB
2024-05-13 13:06:40 Indexing 5/4320 with UID "6" ("https://digital.slub-dresden.de/data/kitodo/5PiG_476250676/5PiG_476250676_mets.xml") on PID 2 and Solr core 1.
Peak usage - begin: 97918 KB
------------------------------------------------------
Current usage 1: 96433 KB - before saveToDatabase()
Current usage 2: 96602 KB - between saveToDatabase() and add()
add() usage 2-1: 96602 KB - before self::$processedDocs check
add() usage 2-2: 96602 KB - after solr connect
add() usage 2-5: 96602 KB - before document save
add() usage 2-6: 96603 KB - after document save
add() usage 2-7: 96735 KB - after processLogical()
add() usage 2-8: 96735 KB - after processPhysical()
add() usage 2-9: 96735 KB - after update()
Current usage 3: 96734 KB - after add()
Current usage 4: 96720 KB - after clearState()
------------------------------------------------------
Peak usage - end: 97918 KB
2024-05-13 13:06:41 Indexing 6/4320 with UID "7" ("https://digital.slub-dresden.de/data/kitodo/6SoG_476247896/6SoG_476247896_mets.xml") on PID 2 and Solr core 1.
Peak usage - begin: 97918 KB
------------------------------------------------------
Current usage 1: 96885 KB - before saveToDatabase()
Current usage 2: 97369 KB - between saveToDatabase() and add()
add() usage 2-1: 97369 KB - before self::$processedDocs check
add() usage 2-2: 97369 KB - after solr connect
add() usage 2-5: 97369 KB - before document save
add() usage 2-6: 97370 KB - after document save
add() usage 2-7: 97492 KB - after processLogical()
add() usage 2-8: 97492 KB - after processPhysical()
add() usage 2-9: 97491 KB - after update()
Current usage 3: 97491 KB - after add()
Current usage 4: 97477 KB - after clearState()
------------------------------------------------------
Peak usage - end: 97918 KB
2024-05-13 13:06:42 Indexing 7/4320 with UID "8" ("https://digital.slub-dresden.de/data/kitodo/6Kepi_47625079X/6Kepi_47625079X_mets.xml") on PID 2 and Solr core 1.
Peak usage - begin: 97918 KB
------------------------------------------------------
Current usage 1: 97526 KB - before saveToDatabase()
Current usage 2: 97676 KB - between saveToDatabase() and add()
add() usage 2-1: 97676 KB - before self::$processedDocs check
add() usage 2-2: 97676 KB - after solr connect
add() usage 2-5: 97676 KB - before document save
add() usage 2-6: 97677 KB - after document save
add() usage 2-7: 97791 KB - after processLogical()
add() usage 2-8: 97791 KB - after processPhysical()
add() usage 2-9: 97790 KB - after update()
Current usage 3: 97790 KB - after add()
Current usage 4: 97776 KB - after clearState()
------------------------------------------------------
Peak usage - end: 97918 KB
2024-05-13 13:06:42 Indexing 8/4320 with UID "9" ("https://digital.slub-dresden.de/data/kitodo/6FuG_476251729/6FuG_476251729_mets.xml") on PID 2 and Solr core 1.
Peak usage - begin: 97962 KB
------------------------------------------------------
Current usage 1: 97828 KB - before saveToDatabase()
Current usage 2: 97995 KB - between saveToDatabase() and add()
add() usage 2-1: 97995 KB - before self::$processedDocs check
add() usage 2-2: 97995 KB - after solr connect
add() usage 2-5: 97995 KB - before document save
add() usage 2-6: 97996 KB - after document save
add() usage 2-7: 98100 KB - after processLogical()
add() usage 2-8: 98100 KB - after processPhysical()
add() usage 2-9: 98099 KB - after update()
Current usage 3: 98099 KB - after add()
Current usage 4: 98085 KB - after clearState()
------------------------------------------------------
Peak usage - end: 98212 KB
2024-05-13 13:06:44 Indexing 9/4320 with UID "10" ("https://digital.slub-dresden.de/data/kitodo/4ArG_476251087/4ArG_476251087_mets.xml") on PID 2 and Solr core 1.
Peak usage - begin: 98212 KB
------------------------------------------------------
Current usage 1: 98117 KB - before saveToDatabase()
Current usage 2: 98230 KB - between saveToDatabase() and add()
add() usage 2-1: 98230 KB - before self::$processedDocs check
add() usage 2-2: 98230 KB - after solr connect
add() usage 2-5: 98230 KB - before document save
add() usage 2-6: 98231 KB - after document save
add() usage 2-7: 98317 KB - after processLogical()
add() usage 2-8: 98317 KB - after processPhysical()
add() usage 2-9: 98316 KB - after update()
Current usage 3: 98316 KB - after add()
Current usage 4: 98302 KB - after clearState()
------------------------------------------------------
Peak usage - end: 98429 KB

......

2024-05-13 15:11:52 Indexing 3946/4320 with UID "3947" ("https://digital.slub-dresden.de/data/kitodo/DresKr_880547324-1902041201_01-v/DresKr_880547324-1902041201_01-v_mets.xml") on PID 2 and Solr core 1.
Peak usage - begin: 1990710 KB
------------------------------------------------------
Current usage 1: 1990599 KB - before saveToDatabase()
Document parent uid: 3947
Document parent uid: 956
add() usage 2-1: 1990939 KB - before self::$processedDocs check
add() usage 2-1: 1990932 KB - before self::$processedDocs check
Current usage 2: 1990921 KB - between saveToDatabase() and add()
add() usage 2-1: 1990921 KB - before self::$processedDocs check
add() usage 2-2: 1990921 KB - after solr connect
add() usage 2-3: 1990921 KB - before handle parent document
add() usage 2-1: 1990954 KB - before self::$processedDocs check
add() usage 2-4: 1990954 KB - after handle parent document
add() usage 2-5: 1990954 KB - before document save
add() usage 2-6: 1990955 KB - after document save
add() usage 2-7: 1990990 KB - after processLogical()
add() usage 2-8: 1991010 KB - after processPhysical()
add() usage 2-9: 1991010 KB - after update()
Current usage 3: 1991009 KB - after add()
Current usage 4: 1990982 KB - after clearState()
------------------------------------------------------
Peak usage - end: 1991161 KB
2024-05-13 15:11:54 Indexing 3947/4320 with UID "3948" ("https://digital.slub-dresden.de/data/kitodo/DresKr_880547324-1893070101_01-v/DresKr_880547324-1893070101_01-v_mets.xml") on PID 2 and Solr core 1.
Peak usage - begin: 1991161 KB
------------------------------------------------------
Current usage 1: 1991007 KB - before saveToDatabase()
Document parent uid: 3948
Document parent uid: 966
add() usage 2-1: 1991351 KB - before self::$processedDocs check
add() usage 2-1: 1991343 KB - before self::$processedDocs check
Current usage 2: 1991333 KB - between saveToDatabase() and add()
add() usage 2-1: 1991333 KB - before self::$processedDocs check
add() usage 2-2: 1991333 KB - after solr connect
add() usage 2-3: 1991333 KB - before handle parent document
add() usage 2-1: 1991370 KB - before self::$processedDocs check
add() usage 2-4: 1991370 KB - after handle parent document
add() usage 2-5: 1991370 KB - before document save
add() usage 2-6: 1991371 KB - after document save
add() usage 2-7: 1991405 KB - after processLogical()
add() usage 2-8: 1991422 KB - after processPhysical()
add() usage 2-9: 1991421 KB - after update()
Current usage 3: 1991421 KB - after add()
Current usage 4: 1991393 KB - after clearState()
------------------------------------------------------
Peak usage - end: 1991560 KB
2024-05-13 15:11:56 Indexing 3948/4320 with UID "3949" ("https://digital.slub-dresden.de/data/kitodo/DresKr_880547324-1895052501_01-v/DresKr_880547324-1895052501_01-v_mets.xml") on PID 2 and Solr core 1.
Peak usage - begin: 1991560 KB
------------------------------------------------------
Current usage 1: 1991418 KB - before saveToDatabase()
Document parent uid: 3949
Document parent uid: 969
add() usage 2-1: 1991762 KB - before self::$processedDocs check
add() usage 2-1: 1991755 KB - before self::$processedDocs check
Current usage 2: 1991744 KB - between saveToDatabase() and add()
add() usage 2-1: 1991744 KB - before self::$processedDocs check
add() usage 2-2: 1991744 KB - after solr connect
add() usage 2-3: 1991744 KB - before handle parent document
Current usage 3: 1991744 KB - after add()
Current usage 4: 1991719 KB - after clearState()
------------------------------------------------------
Peak usage - end: 1991893 KB

....

2024-05-13 15:24:01 Indexing 4320/4320 with UID "4321" ("https://digital.slub-dresden.de/data/kitodo/DresKr_880547324-1937102602_02-a/DresKr_880547324-1937102602_02-a_mets.xml") on PID 2 and Solr core 1.
Peak usage - begin: 2160047 KB
------------------------------------------------------
Current usage 1: 2159891 KB - before saveToDatabase()
Document parent uid: 4321
Document parent uid: 2514
add() usage 2-1: 2160267 KB - before self::$processedDocs check
add() usage 2-1: 2160259 KB - before self::$processedDocs check
Current usage 2: 2160249 KB - between saveToDatabase() and add()
add() usage 2-1: 2160249 KB - before self::$processedDocs check
add() usage 2-2: 2160249 KB - after solr connect
add() usage 2-3: 2160249 KB - before handle parent document
add() usage 2-1: 2160318 KB - before self::$processedDocs check
add() usage 2-4: 2160318 KB - after handle parent document
add() usage 2-5: 2160318 KB - before document save
add() usage 2-6: 2160319 KB - after document save
add() usage 2-7: 2160353 KB - after processLogical()
add() usage 2-8: 2160362 KB - after processPhysical()
add() usage 2-9: 2160361 KB - after update()
Current usage 3: 2160361 KB - after add()
Current usage 4: 2160333 KB - after clearState()
------------------------------------------------------
Peak usage - end: 2160514 KB


 [OK] All done!

It looks that actually the biggest increase in memory usage brings Indexer::processLogical() function.

One obvious reason why size is growing: self::$processedDocs is getting bigger with every iteration.

Other possible reasons are Indexer::solr or Indexer::fields. There is a risk that one of those static variables stores some data incremental.

I'm continuing my investigation.

[beatrycze-volk]

Changes implemented to improve performance:
#1195
#1196
#1197
#1198
#1199
#1200

Feature for enabling the indexing of documents in batches:
#1201