Hello,
I have another question about performance. I have a repeating section which should loop over 1470 complicated objects. In total, a PDF of about 2500 pages should be generated from these 1470 objects. Unfortunately, Docmosis seems to crash over this. Maybe generating this many pages is too much for Docmosis?
In the logs it shows that doing all the reflective calls takes about 1 minute, but after that it waits and waits... and then it starts doing all the reflective calls again, and so on:
...
DEBUG 06 jan 2010 10:36:46 com.docmosis.template.population.ReflectiveObjectDataProvider - #Reflective call# calling getDataProviderCount("totaalLs") on delegate:LsImpl@19362509
DEBUG 06 jan 2010 10:36:46 com.docmosis.template.population.ReflectiveObjectDataProvider - #Reflective call# calling getDataProvider("totaalLs", 0) on delegate:LsImpl@19362509
DEBUG 06 jan 2010 10:36:46 com.docmosis.template.population.ReflectiveObjectDataProvider - #Reflective call# calling getString("info") on delegate:TotaalTypeImpl@21400839
DEBUG 06 jan 2010 10:36:48 com.docmosis.template.population.openoffice.ODFExplodedTemplatePopulator - content population took:41643
DEBUG 06 jan 2010 10:36:48 com.docmosis.template.population.openoffice.ODFExplodedTemplatePopulator - style population took:9
DEBUG 06 jan 2010 10:36:49 com.docmosis.template.population.openoffice.ODFExplodedTemplatePopulator - Populated in 1209
... here it waits and waits, and then starts doing all the previous calls again.
I also get the following warning regularly:
WARN 06 jan 2010 10:41:03 com.docmosis.template.population.openoffice.ContentStreamPopulator - A deferred write has exceeded the in-memory warning threshold. The property "docmosis.populator.deferredwrite.threshold.warn" is set to 8192 and may be increased to allow this type of document to be processed without this warning.
Could this have anything to do with the problem? I understand how I can solve the warning (by editing the property), but I don't understand what's causing the warning.
After about 15 minutes of repeating the reflective calls, it crashes and gives the following error (I tried with an embedded converter first, and then with a local one):
ERROR 06 jan 2010 10:56:21 com.docmosis.document.DocumentProcessor - Converter:Task failed:Conversion Failed
com.docmosis.util.pipeline.TaskException: Conversion Failed
at com.docmosis.converter.openoffice.OpenOfficeConversionWorker.processTask(line:74)
at com.docmosis.util.pipeline.impl.AbstractDataWorker.run(line:98)
at java.lang.Thread.run(Unknown Source)
Caused by: com.docmosis.document.converter.ConversionServiceFailureException: request to open office to "load" took too long and has been aborted.
at com.docmosis.converter.openoffice.AbstractOpenOfficeConnection$HangMonitor.enqueue(line:341)
at com.docmosis.converter.openoffice.AbstractOpenOfficeConnection$HangMonitor.loadDocument(line:280)
at com.docmosis.converter.openoffice.AbstractOpenOfficeConnection.loadDocument(line:51)
at com.docmosis.converter.openoffice.LocalOpenOfficeConverter.convertFile(line:226)
at com.docmosis.converter.openoffice.LocalOpenOfficeConverter.convert(line:194)
at com.docmosis.document.converter.pool.ConverterInstance.convert(line:197)
at com.docmosis.converter.openoffice.OpenOfficeConversionWorker.processTask(line:59)
... 2 more
ERROR 06 jan 2010 10:56:21 be.abc.lsgeneratie.docmosis.LsGenerator - Task failed:Conversion Failed
INFO 06 jan 2010 10:56:21 com.docmosis.SystemManager - Docmosis shutting down
DEBUG 06 jan 2010 10:56:21 com.docmosis.template.population.render.RendererRegistry - Renderer Registry shutting down
DEBUG 06 jan 2010 10:56:21 com.docmosis.converter.openoffice.LocalOpenOfficeConverter - Converter Shutting down
DEBUG 06 jan 2010 10:56:31 com.docmosis.converter.openoffice.BootstrapOpenOfficeConnection - office shutdown not gracefully completed
DEBUG 06 jan 2010 10:56:31 com.docmosis.converter.openoffice.BootstrapOpenOfficeConnection - An error occurred during xDesktop.terminate().
com.sun.star.lang.DisposedException: java.io.EOFException
at com.sun.star.lib.uno.bridges.java_remote.java_remote_bridge$MessageDispatcher.run(java_remote_bridge.java:171)
INFO 06 jan 2010 10:56:31 com.docmosis.SystemManager - Docmosis shut down
INFO 06 jan 2010 10:56:31 com.docmosis.SystemManager - Docmosis shutting down
DEBUG 06 jan 2010 10:56:31 com.docmosis.template.population.render.RendererRegistry - Renderer Registry shutting down
INFO 06 jan 2010 10:56:31 com.docmosis.SystemManager - Docmosis shut down
Any idea why this is happening?
Thanks in advance!
Configuration Options
Hello HoSpiTaL_gHoSt.
Thanks for the great diagnostics again.
The Short Answer:
================
increase the property docmosis.converter.timeout.after in your
docmosis.properties file.
This is a number of milliseconds, so a value of 900000 = 15 minutes.
The Longer Answer:
=================
Docmosis is configured to allow a maximum time for an operation delegated to
OpenOffice to complete. By default this is 120000 (120 seconds). Your document
is so large, OpenOffice cannot load it in less that 120 seconds (it is the load
operation that is failing as indicated by your diagnostics). Increasing the
property from the default setting will allow more time for the operation to
complete. Docmosis is assuming that OpenOffice has crashed and is restarting it,
and trying again. That is why the whole process is repeating and taking a long
time to give up. The number of retries is controlled by another property, but
that value doesn't need to change.
The warning about docmosis.populator.deferredwrite.threshold.warn is letting you
know that the documents you are processing do large amounts of content insertion
that Docmosis normally can achieve in memory (8k by default) but it is flooding
out to disk since it is more than 8k. You can increase this property if your
disks are a performance bottle neck and you have memory to spare. This means you
give Docmosis more memory to work with and sometimes it can help performance. In
your case it won't be noticeable since all the time taken to produce this document
is taken by Open Office - Docmosis does it's bit within the first minute.
Hope that helps.
docmosis.converter.timeout.after works
Thank you very much for the clear explanation.
In total, it took 23 minutes to generate the document which contains 2700 pages for 1470 repeating objects.
First I changed the docmosis.converter.timeout.after to 600000 (10min), but that was still not enough, so I changed it to 1200000 (20min) and then it did work.
I do find it strange that it takes 23 minutes for 1470 objects. I tried a smaller example with 294 objects, and that took less than 3 minutes. So I had expected the generation of 1470 (=294*5) objects to take about 15min, but I suppose that assumption is not correct.
Non-linear duration
Hello HoSpiTaL_gHoSt.
Glad it is working - and that's definitely a large document.
As for extrapolating 3 minutes into 15 minutes - it seems logical, but I guess there's some parts of OpenOffice loading or saving that are non-linear in time vs document size.
Debugged convertor
I turned debugging on for the standalone converter by putting the following code in the runConverter.bat script:
set DEBUG_SETTINGS=-Djava.util.logging.config.file=javaLogging.properties
echo Debuggin Now On
The following logging appeared in the console, which proves that it takes OpenOffice very long to load and save this document. At least now I know why it is taking so long to generate the document:
INFO: Remote Converter listening on port 2100
7-jan-2010 11:06:06 com.docmosis.util.logging.JavaLogger log
FINER: Waiting for a connection...
7-jan-2010 11:06:58 com.docmosis.util.logging.JavaLogger log
FINE: Accepted a connection.
7-jan-2010 11:06:58 com.docmosis.util.logging.JavaLogger log
FINER: Waiting for a connection...
7-jan-2010 11:06:59 com.docmosis.util.logging.JavaLogger log
FINE: readExternal start
7-jan-2010 11:07:36 com.docmosis.util.logging.JavaLogger log
FINE: readExternal end
7-jan-2010 11:16:36 com.docmosis.util.logging.JavaLogger log
FINER: loadDocument took 539677
7-jan-2010 11:16:36 com.docmosis.util.logging.JavaLogger log
FINER: updateTOC took 7
7-jan-2010 11:30:31 com.docmosis.util.logging.JavaLogger log
FINER: saveDocument took 835638
7-jan-2010 11:30:39 com.docmosis.util.logging.JavaLogger log
FINER: closeDocument took 7811
7-jan-2010 11:30:39 com.docmosis.util.logging.JavaLogger log
FINE: writeExternal start
7-jan-2010 11:30:39 com.docmosis.util.logging.JavaLogger log
FINE: writeExternal end
7-jan-2010 11:30:39 com.docmosis.util.logging.JavaLogger log
INFO: No more data to read. Closing client socket.