Profile DITA OT speed on very large DITA project

[raducoravu]

One of our end users shared their 50k topic DITA project with us. It has about 2k DITA submaps.
I started profiling it using JProfiler, one of the problems I encountered is that we are using linkedlists in GenMapAndTopicListModule instead of Linkedhashsets which would yield better results when checked with contains()

No need to document this separately in 3.6 release notes, fixes have been implemented in PRs for 3.6

[raducoravu]

Querying the ANT entity resolver for each parsed topic's DOCTYPE also seems to take some time:

[raducoravu]

The configureSaxonCollationResolver() method also seems to take its time:

[raducoravu]

What I don't like the most is that 3GBs is not enough for the HTML-based output, I need to look into the memory allocations as well.

[raducoravu]

in org.dita.dost.writer.DebugFilter maybe we could keep a cache between attribute class value and DITAClass objects.

[raducoravu]

The project has very many folders, about 10k, in each folder being a couple of topics.
The DITA OT has a grammar pool org.dita.dost.util.XMLGrammarPoolImplUtils which should cache DTDs based on the XMLGrammarDescription descriptions.
An org.apache.xerces.impl.dtd.XMLDTDDescription has an expanded system ID and a public ID, these two fields are used on the equals() and hashcode() methods.
The expanded system ID for each DOCTYPE declaration:

<!DOCTYPE topic PUBLIC "-//OASIS//DTD DITA Topic//EN" "topic.dtd">

is an absolute URL location relative to the DITA topic location. So for a DITA topic which is placed in "c:\Downloads\dita\someFolder", the expanded system ID is "file:/c:/Downloads/dita/someFolder.topic.dita".
This means that the cache keeps accumulating DTDs inside, because it can only cache grammars for the topics located in the same folder really.
Our end user needed to disable this cache in order not to receive the out of memory early in the gen-list stage..

[raducoravu]

If in the "org.dita.dost.util.XMLGrammarPoolImplUtils" we override the equals and hashcode methods to look only at public IDs, the grammars no longer accumulate in the pool and are reused across different folders containing topics:

public int hashCode(final XMLGrammarDescription desc) {
    if (desc instanceof XSDDescription) {
        // return -1 for XSD grammar hashcode because we want to disable XSD grammar caching
        return -1;
    } else {
    	if(desc.getPublicId() != null) {
    		return desc.getPublicId().hashCode();
    	}
        return desc.hashCode();
    }
}

public boolean equals(final XMLGrammarDescription desc1,
        final XMLGrammarDescription desc2) {
    if (desc1 instanceof XSDDescription
            && desc2 instanceof XSDDescription) {
        // always return false for XSD grammar to disable XSD grammar caching
        return false;
    } else {
    	if(desc1.getPublicId() != null && desc2.getPublicId() != null) {
    		return desc1.getPublicId().equals(desc2.getPublicId());
    	}
        return desc1.equals(desc2);
    }
}

[robander]

I hit a problem in my last job with grammar cache and having more than a few hundred directories -- this sounds like it may be hitting the same thing. In that case, we started with about 1,000 folders and a few thousand topics. My test case eventually got to about 400 folders (each with only one topic), and that hit 2 gig memory limits and crashed. Turning off the grammar cache allowed that sample to build quickly.

Moving the same sample files into one directory built very quickly with grammar cache on (even adding a few thousand topics was not a problem). It was definitely an issue with grammar cache + number of directories. I assumed the problem was internal to Xerces at that point though. (I no longer have access to the sample files but I remember that issue pretty clearly from a year ago.)

[raducoravu]

Right, our end user also sets these parameters:

args.grammar.cache=no
generate-debug-attributes=false
conserve-memory=true

the build takes about 4 hours to finish after this but it no longer runs out of memory.

[GCWait]

I joined today's call a little late. Is the above solution planned to go into 3.6?

[jelovirt]

in org.dita.dost.writer.DebugFilter maybe we could keep a cache between attribute class value and DITAClass objects.

Implemented in #3569

[jelovirt]

GenMapAndTopicListModule instead of Linkedhashsets which would yield better results when checked with contains()

Implemented in #3570

[raducoravu]

@GCWait there are a couple of possible problems described here. I was told to add a fix for the grammar pool problem on the 3.5.4 branch because it's a bug. The rest of the enhancements were committed by @jelovirt on the development branch, meaning that indeed they will probably be available in 3.6.

[raducoravu]

@jelovirt to avoid searching in the classpath for extension function definitions in "org.dita.dost.util.XMLUtils.configureSaxonExtensions(Configuration)" each time a parser is being made, we could maybe search for extension function definitions only once lazily and then keep them in a static list.

[raducoravu]

I moved on to the "filter" stage, on each start element the job.getfileinfo seems to stall (or it's just that it's called very often).

[raducoravu]

To remove the delays in org.dita.dost.util.Job.getFileInfo(URI) we would need to have two additional maps in the Job.class, something like:

private final Map<URI, FileInfo> fileSrcToFileInfo = new ConcurrentHashMap<>();
private final Map<URI, FileInfo> fileOutToFileInfo = new ConcurrentHashMap<>();

in this way we would not need to iterate the values to find certain mappings.

[raducoravu]

The serialization of the job also seems to take a while, not sure how that could be enhanced though:

[raducoravu]

The three improvements in the pre-process Java code for which no PRs have been opened are:

XMLUtils.configureSaxonExtensions - search for the possible classes implementors of that specific interface only once.
Job.getFileInfo - keep extra maps between a fileinfo input/output and a FileInfo object to increase the speed of the "getFileInfo" method.
Job.write - somehow make the serialization of the job faster.

[jelovirt]

If in the "org.dita.dost.util.XMLGrammarPoolImplUtils" we override the equals and hashcode methods to look only at public IDs...3574

Fixed in #3574

[jelovirt]

@raducoravu are you able to test the Job serialization, if we add a BufferedOutputStream there

public void write() throws IOException {
        if (!tempDir.exists() && !tempDir.mkdirs()) {
            throw new IOException("Failed to create " + tempDir + " directory");
        }
        try (OutputStream outStream = new BufferedOutputStream(new FileOutputStream(jobFile))) {
            XMLStreamWriter out = null;
            try {
                out = XMLOutputFactory.newInstance().createXMLStreamWriter(outStream, "UTF-8");
                serialize(out, prop, byTemp.values());
            } catch (final XMLStreamException e) {
                throw new IOException("Failed to serialize job file: " + e.getMessage());
            } finally {
                if (out != null) {
                    try {
                        out.close();
                    } catch (final XMLStreamException e) {
                        throw new IOException("Failed to close file: " + e.getMessage());
                    }
                }
            }
        } catch (final IOException e) {
            throw new IOException("Failed to write file: " + e.getMessage());
        }
        lastModified = jobFile.lastModified();
    }

or if OutputStreamWriter is faster at UTF-8 encoding

…
        try (Writer writer = Files.newBufferedWriter(jobFile.toPath())) {
            XMLStreamWriter out = null;
            try {
                out = XMLOutputFactory.newInstance().createXMLStreamWriter(writer);
                serialize(out, prop, byTemp.values());
…

[jelovirt]

The serialization of the job also seems to take a while, not sure how that could be enhanced though:

So how large is the resulting .job.xml file in your test case?

[raducoravu]

Feedback from end user after testing the grammar cache fix:

I can confirm I managed to run the publication on a commodity laptop without issue in 5Gb. I was also able to run the PDF version of the same scenario however that took over 5 hours. The memory was set at 15Gb, having failed at 8Gb.

I suspect the huge amount of memory for PDF is taken by the Apache FOP.

[raducoravu]

@jelovirt the .job.xml size is 22 megabytes and after adding the bufferedoutputstream I did not see any performance problems during the serialization, the serialization was so fast (1-2 seconds) that I did not have time to start the CPU recording when the logging announced that it had begun.

[jelovirt]

Tested with mock data that results in about 23 MB job file. Using a buffer results takes the serialization down to about 0.5% of the original time. So 200 fold performance improvement. I'll create a PR for this.

[jelovirt]

Did some more investigation on the serialization. Actually, it seems the XMLOutputFactory returns a serializer that is really slow in UTF-8 encoding. Using JDK's OutputStreamWriter to handle the encoding gives the 200 fold improvement. Just using the BufferedOutputStream gives almost nothing.

[raducoravu]

Further in the pre-processing, going to the [keyref] stage, when the very large DITA Map is processed (30 MBs, 40k keys, no keyscopes, no keyrefs):

There is probably only one key scope there (the default one) which is hashed multiple times, each hash hashing its 40K descendant keys.

[raducoravu]

the same problem on "KeyrefModule.adjustResourceRenames"

[raducoravu]

The [topic-fragment] stage seems to be applied on all topics, it's purpose seems to be to normalize tables content, normalized codeblocks, expand coderefs. I think few topics in this project have tables and codeblock. Maybe it could be applied only on topics for which it was previosly determined that they have such elements inside...

[raducoravu]

A screenshot from the "chunk" stage, they have about 9000 chunk=to-content. I don't see there anything to be improved but attaching the screenshot nonetheless:

[raducoravu]

The move-meta stage takes a large amount of time on the map.ditamap (which by now has about 40 MBs)
By now it's not our Java code anymore, its the mappull.xsl being applied by Saxon. Such timing problems in the XSLT would probably need to be approached separately, somehow by trying to optimize the XSLTs.

[raducoravu]

The image-metadata module seems to go through all files, although there are only 4 images in the entire project.

[raducoravu]

As an overview, the client said that initially publishing their map to WebHelp took 5 hours (with grammar caching and XSLT document caching disabled) and they did it on a server with about 20 GBs of internal RAM. As you might suspect I never tested that on my side.
After the grammar cache fixes I run the publishing on my side without disabling any caches, it was about 111 minutes and no longer seemed to require much internal memory, 1GB seems to be almost enough.
After adding the speed improvements in GenMapAndTopicListModule and Job.getFileInfo, today it took about 60 minutes.

I did not have the latest Job serialization fix installed.
I also did not have the DITAClass fixed installed.
I'm not sure how much time these two fixes would shave off, maybe a couple of minutes.

I did have an extra fix in "XMLUtils.configureSaxonExtensions" to avoid looking for XSLT extensions every time a transformer is created, fix which in my opinion should also be included.

[raducoravu]

When having so many files, we need to try to avoid going through those files, loading and serializing them back in all stages.
For example the "image-metadata" is as fast as it can be, but just going through 50K files and writing them back with an identity transform takes time. Same for "topic-fragment".

[markgif]

Just want to say I'm really enjoying reading this bug.

[raducoravu]

@jelovirt should we close this issue? I think various performance improvements have been done, also we now have those independent parameters for using the memory as disk and for parallel processing. Independent issues can be further added in the future for example for XSLT profiling if at some point

[jelovirt]

Closing as fixed. New issues should be opened for hot spots found in released code.

[raducoravu]

The project from which this discussion started is now available here:
https://github.com/NHSDigital/DataDictionaryPublication

It is available under Open Government Licence (nationalarchives.gov.uk).