Errors running DROID causing it to not capture all files in reports?

[ross-spencer]

Hi DROID team! 

I'm running DROID on the following machine: 

• Windows XP SP3
  
• 2.66GB memory
  
• I5-2520M 2.50GHz

I'm running it across a collection of 372228 files, 210GB complete size. 

I'm finding that the file count at times is inconsistent. 

For example the run I have just completed reported 372227 files. I was running the scan twice, at the sane time, over the same set of files, and the second report shows 372226 files. 

I don't expect accessing the files at the same time to be a problem. It just happens to be the way I needed to generate two reports overnight. 

I'm also noticing errors in the log from the process:

2014-05-02 16:51:31,660 ERROR [Ljava.lang.StackTraceElement;@bcda40

java.lang.OutOfMemoryError: Java heap space

at uk.gov.nationalarchives.droid.core.interfaces.resource.CachedByteArrays$CacheTransformer.transform(CachedByteArrays.java:106)

at org.apache.commons.collections.map.LazyMap.get(LazyMap.java:158)

at uk.gov.nationalarchives.droid.core.interfaces.resource.CachedByteArrays.readByte(CachedByteArrays.java:126)

at net.domesdaybook.matcher.sequence.searcher.BoyerMooreHorspoolSearcher.searchForwards(BoyerMooreHorspoolSearcher.java:93)

at uk.gov.nationalarchives.droid.core.signature.droid6.SubSequence.findSequenceFromPosition(SubSequence.java:719)

at uk.gov.nationalarchives.droid.core.signature.droid6.ByteSequence.matches(ByteSequence.java:424)

at uk.gov.nationalarchives.droid.core.signature.droid6.InternalSignature.matches(InternalSignature.java:399)

at uk.gov.nationalarchives.droid.core.signature.droid6.InternalSignatureCollection.getMatchingSignatures(InternalSignatureCollection.java:99)

at uk.gov.nationalarchives.droid.core.signature.droid6.FFSignatureFile.runFileIdentification(FFSignatureFile.java:495)

at uk.gov.nationalarchives.droid.core.BinarySignatureIdentifier.matchBinarySignatures(BinarySignatureIdentifier.java:103)

at uk.gov.nationalarchives.droid.submitter.SubmissionGateway$1.call(SubmissionGateway.java:123)

at uk.gov.nationalarchives.droid.submitter.SubmissionGateway$1.call(SubmissionGateway.java:119)

at java.util.concurrent.FutureTask$Sync.innerRun(Unknown Source)

at java.util.concurrent.FutureTask.run(Unknown Source)

at java.util.concurrent.Executors$RunnableAdapter.call(Unknown Source)

at java.util.concurrent.FutureTask$Sync.innerRun(Unknown Source)

at java.util.concurrent.FutureTask.run(Unknown Source)

at uk.gov.nationalarchives.droid.core.interfaces.BlockingThreadPoolExecutorFactory$CallerRunsUnlessPoolShutdownPolicy.rejectedExecution(BlockingThreadPoolExecutorFactory.java:86)

at java.util.concurrent.ThreadPoolExecutor.reject(Unknown Source)

at java.util.concurrent.ThreadPoolExecutor.execute(Unknown Source)

at java.util.concurrent.AbstractExecutorService.submit(Unknown Source)

at uk.gov.nationalarchives.droid.submitter.SubmissionGateway.submit(SubmissionGateway.java:129)

at uk.gov.nationalarchives.droid.submitter.SubmissionGateway$$FastClassByCGLIB$$441edb4e.invoke(<generated>)

at net.sf.cglib.proxy.MethodProxy.invoke(MethodProxy.java:204)

at org.springframework.aop.framework.Cglib2AopProxy$CglibMethodInvocation.invokeJoinpoint(Cglib2AopProxy.java:700)

at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:149)

at org.springframework.aop.framework.adapter.MethodBeforeAdviceInterceptor.invoke(MethodBeforeAdviceInterceptor.java:50)

at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:160)

at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:89)

at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:171)

at org.springframework.aop.framework.Cglib2AopProxy$DynamicAdvisedInterceptor.intercept(Cglib2AopProxy.java:635)

at uk.gov.nationalarchives.droid.submitter.SubmissionGateway$$EnhancerByCGLIB$$985fb67d.submit(<generated>)

2014-05-02 16:51:31,660 ERROR [Ljava.lang.StackTraceElement;@e850c4

java.lang.OutOfMemoryError: Java heap space

at uk.gov.nationalarchives.droid.core.interfaces.resource.CachedByteArrays$CacheTransformer.transform(CachedByteArrays.java:106)

at org.apache.commons.collections.map.LazyMap.get(LazyMap.java:158)

at uk.gov.nationalarchives.droid.core.interfaces.resource.CachedByteArrays.readByte(CachedByteArrays.java:126)

at net.domesdaybook.matcher.sequence.searcher.BoyerMooreHorspoolSearcher.searchForwards(BoyerMooreHorspoolSearcher.java:93)

at uk.gov.nationalarchives.droid.core.signature.droid6.SubSequence.findSequenceFromPosition(SubSequence.java:719)

at uk.gov.nationalarchives.droid.core.signature.droid6.ByteSequence.matches(ByteSequence.java:424)

at uk.gov.nationalarchives.droid.core.signature.droid6.InternalSignature.matches(InternalSignature.java:399)

at uk.gov.nationalarchives.droid.core.signature.droid6.InternalSignatureCollection.getMatchingSignatures(InternalSignatureCollection.java:99)

at uk.gov.nationalarchives.droid.core.signature.droid6.FFSignatureFile.runFileIdentification(FFSignatureFile.java:495)

at uk.gov.nationalarchives.droid.core.BinarySignatureIdentifier.matchBinarySignatures(BinarySignatureIdentifier.java:103)

at uk.gov.nationalarchives.droid.submitter.SubmissionGateway$1.call(SubmissionGateway.java:123)

at uk.gov.nationalarchives.droid.submitter.SubmissionGateway$1.call(SubmissionGateway.java:119)

at java.util.concurrent.FutureTask$Sync.innerRun(Unknown Source)

at java.util.concurrent.FutureTask.run(Unknown Source)

at java.util.concurrent.Executors$RunnableAdapter.call(Unknown Source)

at java.util.concurrent.FutureTask$Sync.innerRun(Unknown Source)

at java.util.concurrent.FutureTask.run(Unknown Source)

at java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source)

at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)

at java.lang.Thread.run(Unknown Source)

2014-05-02 16:51:31,660 ERROR [Ljava.lang.StackTraceElement;@1c07c92

java.lang.OutOfMemoryError: Java heap space

at uk.gov.nationalarchives.droid.core.interfaces.resource.CachedByteArrays$CacheTransformer.transform(CachedByteArrays.java:106)

at org.apache.commons.collections.map.LazyMap.get(LazyMap.java:158)

at uk.gov.nationalarchives.droid.core.interfaces.resource.CachedByteArrays.readByte(CachedByteArrays.java:126)

at net.domesdaybook.matcher.sequence.searcher.BoyerMooreHorspoolSearcher.searchForwards(BoyerMooreHorspoolSearcher.java:93)

at uk.gov.nationalarchives.droid.core.signature.droid6.SubSequence.findSequenceFromPosition(SubSequence.java:719)

at uk.gov.nationalarchives.droid.core.signature.droid6.ByteSequence.matches(ByteSequence.java:424)

at uk.gov.nationalarchives.droid.core.signature.droid6.InternalSignature.matches(InternalSignature.java:399)

at uk.gov.nationalarchives.droid.core.signature.droid6.InternalSignatureCollection.getMatchingSignatures(InternalSignatureCollection.java:99)

at uk.gov.nationalarchives.droid.core.signature.droid6.FFSignatureFile.runFileIdentification(FFSignatureFile.java:495)

at uk.gov.nationalarchives.droid.core.BinarySignatureIdentifier.matchBinarySignatures(BinarySignatureIdentifier.java:103)

at uk.gov.nationalarchives.droid.submitter.SubmissionGateway$1.call(SubmissionGateway.java:123)

at uk.gov.nationalarchives.droid.submitter.SubmissionGateway$1.call(SubmissionGateway.java:119)

at java.util.concurrent.FutureTask$Sync.innerRun(Unknown Source)

at java.util.concurrent.FutureTask.run(Unknown Source)

at java.util.concurrent.Executors$RunnableAdapter.call(Unknown Source)

at java.util.concurrent.FutureTask$Sync.innerRun(Unknown Source)

at java.util.concurrent.FutureTask.run(Unknown Source)

at java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source)

at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)

at java.lang.Thread.run(Unknown Source)

2014-05-02 16:51:31,660 ERROR [Ljava.lang.StackTraceElement;@43180f

java.lang.OutOfMemoryError: Java heap space

at uk.gov.nationalarchives.droid.core.interfaces.resource.CachedByteArrays$CacheTransformer.transform(CachedByteArrays.java:106)

at org.apache.commons.collections.map.LazyMap.get(LazyMap.java:158)

at uk.gov.nationalarchives.droid.core.interfaces.resource.CachedByteArrays.readByte(CachedByteArrays.java:126)

at net.domesdaybook.matcher.sequence.searcher.BoyerMooreHorspoolSearcher.searchForwards(BoyerMooreHorspoolSearcher.java:93)

at uk.gov.nationalarchives.droid.core.signature.droid6.SubSequence.findSequenceFromPosition(SubSequence.java:719)

at uk.gov.nationalarchives.droid.core.signature.droid6.ByteSequence.matches(ByteSequence.java:424)

at uk.gov.nationalarchives.droid.core.signature.droid6.InternalSignature.matches(InternalSignature.java:399)

at uk.gov.nationalarchives.droid.core.signature.droid6.InternalSignatureCollection.getMatchingSignatures(InternalSignatureCollection.java:99)

at uk.gov.nationalarchives.droid.core.signature.droid6.FFSignatureFile.runFileIdentification(FFSignatureFile.java:495)

at uk.gov.nationalarchives.droid.core.BinarySignatureIdentifier.matchBinarySignatures(BinarySignatureIdentifier.java:103)

at uk.gov.nationalarchives.droid.submitter.SubmissionGateway$1.call(SubmissionGateway.java:123)

at uk.gov.nationalarchives.droid.submitter.SubmissionGateway$1.call(SubmissionGateway.java:119)

at java.util.concurrent.FutureTask$Sync.innerRun(Unknown Source)

at java.util.concurrent.FutureTask.run(Unknown Source)

at java.util.concurrent.Executors$RunnableAdapter.call(Unknown Source)

at java.util.concurrent.FutureTask$Sync.innerRun(Unknown Source)

at java.util.concurrent.FutureTask.run(Unknown Source)

at java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source)

at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)

at java.lang.Thread.run(Unknown Source)

The concern is that if this is a memory issue of some sort, and DROID can't report on it, then I have no way of knowing whether DROID ran truly successfully. 

I noticed the error running DROID across this set of files, twice, and a second set of 21,800 files, and this resulted in different counts of. 168904 and 196276 and I've no way of telling there was a problem via the user interface. 

Unfortunately I didn't capture the logs for that. 

I could probably do with a hand verifying this issue and what some of the logging above means, before this is reported on GitHub.

If useful, I can create two more copies of these files for me to run the same test on and observe what happens, although, as mentioned I'd be surprised if concurrent access was an issue. And if it was, perhaps reporting on that is important too. 

Hope this helps. Let me know if I can provide any more information.

Thanks,

Ross

[Matt Palmer]

Hi Ross,

The dreaded put of memory error again! When you hit that there's often little that can be done for obvious reasons. We never entirely figured out what was causing so much pressure on the heap intermittently.

Have you tried upping the memory for Java in the Droid startup script?

Matt

[Graham Seaman]

Hi Ross

It does look like there's a general issue of DROID logging and swallowing system errors (lack of disk and heap space in particular) without sufficient user notification, and I think it's something that does need adding to the todo list.

What were you thinking of in terms of 'giving a hand' in the meantime?

Graham

[ross-spencer]

Hi Graham, Matt, 

I think knowing that there is an awareness of this issue is enough for now. It means I will have to focus on a work around and gathering my information in a different way. 

I'll have a look at upping memory, thanks Matt. 

I plan on running this again on copies of my data, so can generate fresh logging if that is useful in solving this at all? I think I've seen more extreme differences in count so want to verify this. 

It is good to know that it is going to be on the TODO list. File count is the only problem I've seen thus far. I presume the files DROID reports back on, it does so accurately still, in face of such issues? As such, one thing I can think that might be useful, is a pre-calculation of the number of files that DROID is going to scan across. On export, or even scan completeion, a comparison between that and the number of lines/files exported, with a warning if there is any difference would be a great start. We'd know we've a report that we can't rely on. 

Understanding how we approach using DROID, and relying on it, in the face of any inconsistencies is a more difficult challenge. 

Many thanks,

Ross

[ross-spencer]

Hi All, 

To demonstrate the effect of this issue I ran DROID across three sets of files at the same time, two copies of the same set at 372228 in count and another at 21822 in size.

I tried to capture the logs but it seems there are no Java errors in there. However, the row counts for the reports are as follows:

Set 1: 372228 out of 372228

Set 2: 338557 out of 372228

Set 3: 21822 out of 21822

As you can see, the count in the second set is seriously off.

I'm not really sure what I can do to help to provide more information here, I suppose it's just a demonstration of how non-trivial the issue can be. 

Let me know if you have any ideas.

Thanks,

Ross

[Brian O'Reilly]

Hi Ross

I'm currently looking into this issue.  Are you able to provide any further information as to:

- the version of the JVM on which you were running DROID when this occured
- detaills about which files were skipped. On this point, it would be interesting to establish whether specific files are skipped on successive runs, or whether the skipping of files is more random.
- any changes to the default profile options, such as scanning more than than the default number of bytes, or asking for MD5 hashes to be generated.
Clearly it might take a number of runs to get reliable data on this point, however anything you can provide would be much appreciated.

So far I've made a number of test runs (with default options) over a drive containing 787 GB of data (around 261,000 files), and have not encountered the same issue.  The environment was Windows 7 64-bit, JRE Version 1.8.0_85 (I was using a Java 8 test build , though early results indicate a similar outcome using Java 7 (1.7.0_45)).  I am currently running some further tests using a reduced heap size to see if I can reproduce the problem.

Thanks, Brian