Too many open files
Brought to you by:
aventin
Menu
▾
▴
#191 Too many open files
Operating System: Ubuntu 8.04
Areca Version: 7.0.6
Java Version: 1.6.0_07
Using the command line client (graphical environment unavailable), it appears there is a problem with holding file handles open. When it appears to be transferring large files, the file handles remain low. When transferring a large amount of small files, the file handles grow quite a bit. If allowed to grow beyond 1024 open handles, it malfunctions. It appears that when the app is done with a file handle it is not closing it, but rather allowing it to be closed through GC or other delayed mechanism.
I am unable to complete a backup on this particular system.
09-03-11 11:19 - ERROR
java.io.IOException: Cannot run program "ls": java.io.IOException: error=24, Too many open files
at java.lang.ProcessBuilder.start(ProcessBuilder.java:459)
at java.lang.Runtime.exec(Runtime.java:593)
at java.lang.Runtime.exec(Runtime.java:466)
at com.myJava.file.metadata.posix.basic.DefaultMetaDataAccessor.getMetaData(DefaultMetaDataAccessor.java:58)
at com.myJava.file.driver.DefaultFileSystemDriver.getMetaData(DefaultFileSystemDriver.java:342)
at com.myJava.file.FileSystemManager.getMetaData(FileSystemManager.java:421)
at com.application.areca.metadata.trace.ArchiveTraceParser.serialize(ArchiveTraceParser.java:232)
at com.application.areca.metadata.trace.ArchiveTraceAdapter.writeEntry(ArchiveTraceAdapter.java:75)
at com.application.areca.impl.AbstractIncrementalFileSystemMedium.store(AbstractIncrementalFileSystemMedium.java:1149)
at com.application.areca.AbstractRecoveryTarget.processBackup(AbstractRecoveryTarget.java:332)
at com.application.areca.TargetGroup.processBackupOnTarget(TargetGroup.java:220)
at com.application.areca.launcher.tui.Launcher$1.run(Launcher.java:254)
at java.lang.Thread.run(Thread.java:619)
Caused by: java.io.IOException: java.io.IOException: error=24, Too many open files
at java.lang.UNIXProcess.<init>(UNIXProcess.java:148)
at java.lang.ProcessImpl.start(ProcessImpl.java:65)
at java.lang.ProcessBuilder.start(ProcessBuilder.java:452)
... 12 more
Using single file archive seems to reduce this effect due to slowing down the process with compression, and reducing the number of handles being opened at once by approximately half.
This is still a bug, though, as it makes no-compression backups unusable in the case that I am encountering.
Hi
This is a really strange bug (which I successfully reproduced on my own machine)
It seems to happen only in case of delta archives, stored as standard (or individually compressed files).
I checked Areca's file handle management (to make sure that it doesn't leave files open), but all seems ok ...
Strangely, reducing the value of fs.buffer.size in the fwk.properties file to 100000 seems to make these errors disappear (!!??)
I looked at some documentation on this and there actually appears to be a bug in Java (including latest versions) where using file handles to issue system commands can leave the handle open. I have one of the pages I read on this saved somewhere that possibly had a workaround. I'll try to find it.
When I get a chance, I'll set up a test target on my linux box to test this change and monitor handles. I don't think the bug just goes away, but probably causes GC to happen more frequently with the reduced buffer, which is something I was actually trying to figure out (increase GC frequency) to try to get the handles cleaned up more frequently and prevent hitting the limit.
Using compression is very slow so if this works, I'll be happy.
The bug still occurs when the "track file permissions" (which actually causes Areca to issue system commands) is unchecked.
So it is probably caused by standard file access rather than system commands
Just wanted to post an observation while I'm testing. I added the following to the java command in areca_cl.sh so I can monitor garbage collection:
-Xloggc:/tmp/$$.log -verbosegc
The application is doing a lot of minor GC. In most cases, during the backup process, it will perform multiple minor GC per second. Unless GC is parallel (documentation is a bit sparse on the default outside of various implementations of version 1.4 of the jvm), I would expect this to adversely impact performance.
Anyway, none of the minor GC appear to free up handles. Only when one of the infrequent Full GC is triggered does it free up handles. This is before making the change to fwk.properties. I'm going to save the GC log of before and after.
I have further observations. It takes a long time to establish anything so forgive the length of testing ;)
The GC logging only confirmed that a Full GC is the only time it cleans up handles. Reducing fs.buffer.size does not make the problem go away, and only seems to increase frequency of Full GC (as suspected).
My backup stopped crashing on the linux box (I did some file cleanup, so I guess I removed the conditions to cause it) but handle count still climbs very high (a few times I saw it above 900, when the limit is 1024).
With the value of 100000 on fs.buffer.size, the handle count still climbs pretty high. Since the crashing stopped before I changed it, I can't really compare it well, other than to note that the handle count, so far, has not gotten as high as it did before the change. I may lower the value even further to see the effect on handles, then do some timed tests to see how it impacts performance.
Anyway, lowering this buffer may just be a bandaid. I'll start browsing code if I get a chance (busy with work lately).
Setting fs.buffer.size to 50000 further reduces the max handles consumed and does not appear to impact performance. I will stick with this setting for now.
Thanks a lot for your investigations.
I think I'll release a quick fix that limits the value of fs.buffer.size to 50000 ... this is not very pretty, but it will give me some time to investigate further ...
I finally found the problem ... file handles were correctly managed for write accesses, but not for read accesses
It is fixed in v7.0.7
Thx for your help !