Troubleshooting an Oracle UCM Batch Loader performance problem

by Jeremy Cook on 20 April 2016

One of our largest clients has recently gone through the process of migrating upwards of 60 million client documents from an old Stellent enterprise document management system to the newer Oracle Universal Content Management (UCM) system.

The Oracle Batch Loader is a Java utility for loading large numbers of documents, saving the manual effort of manually loading those documents through the standard Oracle UCM check-in interface. It is integrated into Oracle Fusion Middleware as part of the Oracle WebCenter Content (WCC) product. The utility immediately releases the document after loading and does not put them into any workflow process.

Our client found the performance of the Oracle UCM Batch Loader to be slower than expected, putting at risk the migration project’s ability to deliver within the expected timeframe and budget. Wild Strait was engaged to troubleshoot the performance problem.

Troubleshooting the performance problem with Oracle UCM Batch Loader

In this section I get a little bit technical, but I am writing for a technical audience who may need to resolve performance issues of this type.

During general troubleshooting miscellaneous issues were resolved in many parts of the infrastructure such as the Oracle Real Application Clusters (RAC), Oracle Storage Architect Manager (SAM-QFS) and the Oracle Network File System (NFS). While it was great to identify and fix these problems, performance still remained at about 80-120KB/sec throughput of document migration in the Batch Loader. The bottleneck appeared to be the Batch Loader java process.

A quick look at the utility top didn’t show up much, but the utility iotop uncovered between 80% to 100% i/o for one of the threads in the Batch Loader java process.

iotop `ps -Teo pid,tid | grep pid_of_batchloader | awk '{printf" -p %s",$2}'`

The ps command has an extremely useful option wchan that shows which kernel function the thread (tid = thread ID) is sleeping in.

ps -eTo pid,tid,wchan=WIDE-WCHAN-COLUMN | egrep 'top_tid_1 | top_tid_2 | top_tid_3 | etc '

Using this ps output on the top handful of java Batch Loader threads from iotop I saw the process was spending:

80% in sync_page (File mapping function: waiting on i/o but perhaps also waiting for a page lock; (refer to filemap.c))
10% in sk_wait_data. (socket buffer function: wait for data to arrive at sk_receive_queue)
A tiny bit in sk_stream_wait_memory (socket buffer function: wait for more memory for a socket)

So I used pstack and the similar java command jstack to get a view on what Batch Loader was doing with those sync_pages.

jstack pid_of_batchloader | grep -A10 tid_with_highest_wio

Turns out they were java.io.FileInputStream.readBytes requested by the Oracle UCM (historically called Intradoc classes) via Oracle JDBC (see stack trace below).

To check whether the Batch Loader i/o was being held up on a different infrastructure tier by SAM-QFS followed by NFS, I gave the Batch Loader a theoretical help along by writing a small shell script to iterate through a batch of primaryFiles (one of the metadata fields holding the document filename) in the Batch Loader input file then using dd command to copy them from SAM-QFS to /dev/null so they would be in the Linux filesystem cache.

Potential performance problem areas

Using dd, we confirmed areas for potential optimisation:

Unstaged files on SAM-QFS came across NFS at a few KB/sec
Staged files came across NFS at over 100MB/sec
Different document formats were transferred faster than others (due to size)

We won’t go into staging discussion here except to say some work was done to ensure batches of documents were fully staged in advance, then unstaged at the end so as not to overfill SAM-QFS caches. There was opportunity for further performance investigation relating to SAM-QFS configuration but this was left for later.

But pre-cached documents in the filesystem cache did not speed up the Batch Loader process and at that point I had two theories:

that java.io.FileInputStream.readBytes ignores the o.s. file cache
that the batchloader java.io.FileInputStream.readBytes is buffered inappropriately low.

Narrowing in on the performance problem

I had written a small test program to compare java.io.FileInputStream.readBytes with other methods and found we were using the second slowest. This is an example output from the test (times in ms to read a 67MB file):

BufferedInputStream read: 2804 ByteArrayInputStream read: 1976 DataBufferByte read: 349 ByteBuffer read: 357 RandomAccessFile read: 80365 byte[] read: 0 (from reading about this, my microcode test needs work and the byte[] call is mega fast) MappedByteBuffer read: 35 FileInputStream read: 65744 (this is the one being used, and it is very slow)

A colleague's interest was sparked again and he did a quick java test program too, but instead tested using a variable sized buffer (read chunk size) with just java.io.FileInputStream.readBytes. Note how much faster the reads become with increasing byte array.

# for bytes in 1 10 50 100 200 500 1000; do java ReadFileTest /NFS_NFR121_02/storage/content/2010/Jan/25/06/nfr_121_02_0020034438-02.pdf $bytes ; done

Read 420689 bytes in 278 milliseconds using 420689 loop iterations. Array size: 1Read 420689 bytes in 26 milliseconds using 42070 loop iterations. Array size: 10Read 420689 bytes in 7 milliseconds using 8415 loop iterations. Array size: 50Read 420689 bytes in 4 milliseconds using 4208 loop iterations. Array size: 100Read 420689 bytes in 2 milliseconds using 2105 loop iterations. Array size: 200Read 420689 bytes in 1 milliseconds using 843 loop iterations. Array size: 500Read 420689 bytes in 1 milliseconds using 422 loop iterations. Array size: 1000

This was very interesting and as can be seen in the jstack output below Oracle uses java.io.FileInputStream.read(byte[], int, int) - so it is reading chunks at particular offsets and probably rescanning offSetLength every time it had to access the file.

Is the Chunk size byte[] call too small?

So our question then was why was the Batch Loader filesystem read performance so poor? Was it because the chunk size byte[] from the java.io.FileInputStream.read(byte[], int, int) call was too small?

At this point I compared some classes in ojdbc6.jar (which we were using) and the newer ojdbc7.jar. There was a 8x increase in lots of places where arrays and chunk sizes were set up, particularly the byte[] array we were interested in. Some cursory checks for compatibility were done (JDK7, Oracle RAC 11g) and we tried using the Batch Loader with ojdbc7.jar.

Using Batch Loader with ojdbc7.jar gave a 38% performance increase

Using ojdbc7.jar we obtained a 38% performance increase on this occasion and saved the client weeks of migration batch loading time.

In future I think if they were to repeat this migration exercise, we would recommend evaluating the IdcCommand utility or even the HTTP API instead of the aging Batch Loader.

This is an example stack output showing the classes used. The final one (at the top) is a non-java private native C function (JNI).

Thread 1011: (state = IN_NATIVE)

- java.io.FileInputStream.readBytes(byte[], int, int) @bci=0 (Compiled frame; information may be imprecise)

- java.io.FileInputStream.read(byte[], int, int) @bci=16, line=272 (Compiled frame)

- oracle.jdbc.driver.OracleConversionInputStream.needBytesFromStream() @bci=103, line=334 (Compiled frame)

- oracle.jdbc.driver.OracleConversionInputStream.needBytes() @bci=30, line=211 (Compiled frame)

- oracle.jdbc.driver.OracleConversionInputStream.needBytes(int) @bci=1, line=191 (Compiled frame)

- oracle.jdbc.driver.OracleBufferedStream.readInternal(byte[], int, int) @bci=43, line=169 (Compiled frame)

- oracle.jdbc.driver.OracleBufferedStream.read(byte[], int, int) @bci=16, line=143 (Compiled frame)

- oracle.jdbc.driver.T4CTTIrxd.marshal(byte[], char[], short[], int, byte[], oracle.jdbc.driver.DBConversion, java.io.InputStream[], byte[][], oracle.jdbc.oracore.OracleTypeADT[], byte[], char[], short[], byte[], int, int[], boolean, int[], int[], int[][]) @bci=2056, line=792 (Compiled frame)

- oracle.jdbc.driver.T4C8Oall.marshalBinds(int[]) @bci=191, line=1678 (Compiled frame)

- oracle.jdbc.driver.T4C8Oall.marshal() @bci=236, line=1041 (Compiled frame)

- oracle.jdbc.driver.T4CTTIfun.doRPC() @bci=44, line=190 (Compiled frame)

- oracle.jdbc.driver.T4C8Oall.doOALL(boolean, boolean, boolean, boolean, boolean, oracle.jdbc.internal.OracleStatement$SqlKind, int, byte[], int, oracle.jdbc.driver.Accessor[], int, oracle.jdbc.driver.Accessor[], int, byte[], char[], short[], int, oracle.jdbc.driver.DBConversion, byte[], java.io.InputStream[][], byte[][][], oracle.jdbc.oracore.OracleTypeADT[][], oracle.jdbc.driver.OracleStatement, byte[], char[], short[], oracle.jdbc.driver.T4CTTIoac[], int[], int[], int[], oracle.jdbc.driver.NTFDCNRegistration) @bci=769, line=531 (Compiled frame)

- oracle.jdbc.driver.T4CPreparedStatement.doOall8(boolean, boolean, boolean, boolean, boolean) @bci=749, line=207 (Compiled frame)

- oracle.jdbc.driver.T4CPreparedStatement.executeForRows(boolean) @bci=226, line=1044 (Compiled frame)

- oracle.jdbc.driver.OracleStatement.doExecuteWithTimeout() @bci=299, line=1329 (Compiled frame)

- oracle.jdbc.driver.OraclePreparedStatement.executeInternal() @bci=119, line=3593 (Interpreted frame)

- oracle.jdbc.driver.OraclePreparedStatement.executeUpdate() @bci=13, line=3674 (Interpreted frame)

- oracle.jdbc.driver.OraclePreparedStatementWrapper.executeUpdate() @bci=4, line=1354 (Compiled frame)

- intradoc.jdbc.JdbcWorkspace.execute(java.lang.String, intradoc.data.Parameters) @bci=102, line=643 (Compiled frame)

- intradoc.filestore.jdbc.JdbcStorage.executeStoreQuery(java.lang.String, intradoc.data.Parameters, intradoc.data.Workspace, intradoc.common.ExecutionContext) @bci=28, line=887 (Interpreted frame)

- intradoc.filestore.jdbc.JdbcStorage.saveStream(java.io.InputStream, intradoc.data.Parameters, java.lang.String, intradoc.data.Workspace, intradoc.common.ExecutionContext) @bci=133, line=186 (Interpreted frame)

- intradoc.filestore.jdbc.JdbcStorage.storeFromInputStream(intradoc.filestore.IdcFileDescriptor, java.io.InputStream, java.util.Map, intradoc.common.ExecutionContext) @bci=207, line=143 (Interpreted frame)

- intradoc.filestore.jdbc.JdbcStorage.storeFromLocalFile(intradoc.filestore.IdcFileDescriptor, java.io.File, java.util.Map, intradoc.common.ExecutionContext) @bci=52, line=92 (Interpreted frame)

- intradoc.filestore.filesystem.FileSystemAccessImplementor.storeFromLocalFile(intradoc.filestore.IdcFileDescriptor, java.io.File, java.util.Map, intradoc.common.ExecutionContext) @bci=41, line=92 (Interpreted frame)

- intradoc.filestore.filesystem.BaseAccessImplementor.storeFromStreamWrapper(intradoc.filestore.IdcFileDescriptor, intradoc.common.DataStreamWrapper, java.util.Map, intradoc.common.ExecutionContext) @bci=35, line=149 (Interpreted frame)

- intradoc.filestore.BaseFileStore.storeFromStreamWrapper(intradoc.filestore.IdcFileDescriptor, intradoc.common.DataStreamWrapper, java.util.Map, intradoc.common.ExecutionContext) @bci=9, line=468 (Interpreted frame)

- intradoc.server.DocServiceHandler.addFileToFileStore(java.lang.String, intradoc.common.DataStreamWrapper) @bci=269, line=3949 (Interpreted frame)

- intradoc.server.DocServiceHandler.addFile(java.lang.String, java.lang.String, boolean) @bci=417, line=3892 (Compiled frame)

- intradoc.server.DocServiceHandler.addFiles() @bci=136, line=528 (Interpreted frame)

- sun.reflect.GeneratedMethodAccessor16.invoke(java.lang.Object, java.lang.Object[]) @bci=36 (Interpreted frame)

- sun.reflect.DelegatingMethodAccessorImpl.invoke(java.lang.Object, java.lang.Object[]) @bci=6, line=43 (Compiled frame)

- java.lang.reflect.Method.invoke(java.lang.Object, java.lang.Object[]) @bci=57, line=606 (Compiled frame)

- intradoc.common.IdcMethodHolder.invokeMethod(java.lang.Object, java.lang.Object[], boolean) @bci=57, line=86 (Compiled frame)

- intradoc.common.ClassHelperUtils.executeMethodReportStatus(java.lang.Object, java.lang.String) @bci=23, line=324 (Compiled frame)

- intradoc.server.ServiceHandler.executeAction(java.lang.String) @bci=15, line=79 (Compiled frame)

- intradoc.server.Service.doCodeEx(java.lang.String, intradoc.server.ServiceHandler) @bci=69, line=622 (Compiled frame)

- intradoc.server.Service.doCode(java.lang.String) @bci=3, line=594 (Compiled frame)

- intradoc.server.ServiceRequestImplementor.doAction(intradoc.server.Service, intradoc.data.DataBinder, intradoc.server.Action) @bci=647, line=1693 (Compiled frame)

- intradoc.server.Service.doAction() @bci=13, line=566 (Compiled frame)

- intradoc.server.ServiceRequestImplementor.doActions(intradoc.server.Service, intradoc.data.DataBinder) @bci=114, line=1483 (Compiled frame)

- intradoc.server.Service.doActions() @bci=9, line=561 (Interpreted frame)

-intradoc.server.ServiceRequestImplementor.executeSubServiceCode(intradoc.server.Service, intradoc.server.Service, intradoc.data.DataBinder, boolean, boolean) @bci=177, line=1346 (Interpreted frame)

- intradoc.server.Service.executeSubServiceCode(intradoc.server.Service, boolean, boolean) @bci=12, line=4184 (Interpreted frame)

- intradoc.server.ServiceRequestImplementor.executeServiceEx(intradoc.server.Service, intradoc.data.DataBinder, java.io.OutputStream, java.lang.String, boolean) @bci=181, line=1222 (Interpreted frame)

- intradoc.server.Service.executeServiceEx(java.lang.String, boolean) @bci=15, line=4179 (Interpreted frame)

- intradoc.server.Service.executeService(java.lang.String) @bci=3, line=4163 (Interpreted frame)

- intradoc.server.ArchiveCheckinHandler.processCheckinArchive() @bci=69, line=196 (Interpreted frame)

- sun.reflect.GeneratedMethodAccessor8.invoke(java.lang.Object, java.lang.Object[]) @bci=36 (Interpreted frame)