We're running the standalone svnkit + jna on Solaris: SunOS unknown 5.10 Generic_142910-17 i86pc i386 i86pc
Our application is constantly failing on commit attempt with 'permission denied'
svn: Cannot read from 'somefile': somefile (Permission denied)
We tried the code on different platforms without any issues (Windows/Linux). We are pretty sure that file system permissions are setup correctly and it's not the problem - the exact same issue appears for every client that is running on Solaris.
You'll find the svnkit logs with full stacktrace in attachment. Please take a look.
Thank you for the log file. May I ask you a few more questions regarding this issue:
1. Is this issue only reproducible with JNA library on classpath? On the email your colleague reported that this issue is JNA-related, is that correct? 2. What version of JDK do you use? 3. What version of SVNKit do you use? Did you try newest 1.7.4-v1 version with the new working copy format?
We have installed Solaris OS on a virtual machine and so far did not manage to reproduce the problem both with SVNKit 1.3.5 and newer 1.3.7 version.
Regarding the exception itself (permission denied) - one of the possible reasons for that exception (besides actual permissions problem) is that there is another process running which reads, writes or deletes temporary file at the same time when commit operation is running. Among such processes there are usually antivirus software or indexing programs that tracks and watches files being created or modified. So, if possible, please check if there are such background process running on your Solaris box and disable it to check if it may be the reason of the problem.
1. Yes, the issue is reproducible only with JNA on the classpath. If we remove JNA all tests complete successfully but performance is significantly degraded. 2. JDK is in version: Sun 1.6.0_24 (50.0), VM: Java HotSpot(TM) 64-Bit Server VM, build: 19.1-b02, mixed mode 3. We tried newest 1.7.4-v1 with JNA in classpath and it looks that access denied problem is gone - version prior 1.7.4-v1 were braking for us due to issue. With 1.7.4-v1 + JNA performance is really weak (average the same as 1.3.5 w/o JNA) so it seems that JNA is not used. Is there a way I can verify that SVNKIT is actually using JNA?
It's good news that with 1.7.4-v1 the issue is resolved however the same performance score as 1.3.5 w/o JNA makes us believe JNA is not used at all (it is in classpath). Could you please help us troubleshooting this?
When running 1.7.4-v1 with JNA we don't see any library related to jnidispatch in temporary dir. For 1.3.5 with JNA - jnidispatch lib is properly created in temp dir and loaded from there.
Verified background processes - there are no other processes that access svnkit temporary files. Thanks for your help!
SVNKit 1.7.4-v1 uses newer version of JNA (JNA 3.4.0). I've just tested it on Windows and JNA is used by SVNKit. Unfortunately there is no information written to log in that version on whether JNA is actually used, but you may calls SVNJNAUtil.isJNAPresent/Enabled methods at runtime to check whether JNA is present and used.
We will check if JNA is used by 1.7.4-v1 on our VM Solaris.
With JDK 1.6 there is no way to improve performance without JNA been used. However, if you could switch to 1.7 then you may expect better performance without JNA as soon as we add JDK new IO API support to SVNKit, which we expect to do in a few weeks.
Thanks! I'll keep you updated on the status of our investigations.
I've performed more test with SVNKit 1.7.4-v1 on Solaris in VirtualBox:
Solaris version (64 bit): SunOS unknown 5.10 Generic_147441-01 i86pc i386 i86pc
Java version: Java(TM) SE Runtime Environment (build 1.6.0_26-b03) Java HotSpot (TM) Client VM (build 20.1-b02, mixed mode, sharing)
SVNKit 1.7.4-v1 (with additional logging)
With the above configuration I can confirm that JNA (version 3.4.0) is loaded and used, commit works fine both with the old and new working copy formats.
Try using that build and then please send me the log file (or attach it to this issue). This log will contain more information on JNA usage.
To disable new working copy format support (so, that working copies are created in the old format, same as used by SVNKit 1.3.7), you may use the following command line argument:
Thank you for the details and new build. I did the test with provided svnkit snapthot and here are the logs attached - svnkit_logs_for_SNAPSHOT_r9229_v20120518_2250.zip.
With this version I'm getting exceptions the NETWORK: svn: E210004: Malformed network data. Error is persistent with 1.7.4-v2 - I repeated the test with 1.7.4-v1 to verify if it's something introduced with 1.7.4-v2 - with old version test completed successfully.
First, regarding "malformed data" error: accordingly to the log it is caused by "Connection Reset" exception, which means that TCP/IP connection is closed on the server side. One of the reasons might be server-side socket write timeout (when it takes too long for the client to process data being received), other reasons are mostly related to the firewall/iptables configuration. You report that 1.7.4-v1 does not suffer from that issue, are you confident about it? May it be that 1.7.4-v1 also fails occasionally with the same error? At least so far I can't see any changes between v1 and v2 that might affect network related code in SVNKit. I will continue to look for.
Second, from the log it could be understood that SVNKit does not use JNA properly in your environment. It loads it, uses but finally receives wrong results and runs pure Java substitution code to get proper file type for instance. This slow downs the execution, plus it may theoretically result in other issues (like originally reported "permission denied" one).
The reason of that problem is that SVNKit JNA-related code for Solaris is only valid for 32-bit system and you run Java in 64-bit mode. On my VM Solaris I could not reproduce JNA-issues when run "jsvn" script (that invokes "java ...") but I did manage to reproduce output similar to those you have in log when add "-d64" to the java command line arguments. Do you pass this argument (-d64 or -server) to "java" program? Could you please try removing it to see if it resolves JNA-related problems?
Meanwhile we will try to add code that handles 64-bit environment on Solaris properly.
I tried your recommendation and set "-d32" switch and verified that JVM was indeed in Java Data Mode 32-bit. This time there was no 'malformed data' so it really could be transient issue. Test completed successfully without issues but with poor performance so it seems JNA is still not used.
Please find the log attached: svnkit_logs_v2_20120523 (it's split with zip into two archives since exceeded the upload limit for one file) Let me know if you would need any other details.
Unfortunately I can't open logs (I've concatenated these two files, but zip program says it is not a valid archive). Could you please run a smaller checkout (like check out a few folders) - this would be enough to see if JNA is used and log will be much shorter.
Another thing to check is whether "-d32" indeed makes JVM run in 32-bit mode. In documentation it is said, that on pure 64-bit Solaris systems, only 64-bit mode is available and 32-bit is ignored. To check this, run "java -d32 version" and "java -version" (or "java -d64 -version") commands. You'll see whether or not 64-bit JVM is used, it should not be used in the first case.
In case -d32 option is ignored and JVM is always ran in 64-bit mode, then you'll have to wait until we add support for 64-bit Solaris to SVNKit JNA-related code. I expect it to be added in a week or so.
Thanks for your suggestions. I tried the simple commit (logs are small) for both cases -d32 and -d64. Please find attached to the ticket. I'm including also the screenshot with details for check with 'java -dXX -version'.
Thank you for the logs. Now your logs are similar to those I'm getting in Virtual Box. JNA was not used properly in 64-bit mode, but it was used properly in 32-bit mode. In case you experience performance issues in 32-bit mode too, then they might be not related to the JNA (or JNA calls themselves might be slow on Solaris in 32 bit mode).
Meanwhile, I've fixed SVNKit JNA code to work properly on 64-bit Solaris, both in trunk and in 1.3.x branch. Fix in 1.3.x is included into 1.3.8 bugfix release that will be published today, and trunk fix will be part of SVNKit 1.7.5 that will be released next week.
Thank you for the update. I tried the 1.3.8 release in 64-bit mode - looks the JNA library is loaded now and tests passed successfully. To see dynamic libraries loaded by JVM I used Solaris' 'pldd' - with it I can see that for JVM process there is linked file: /var/tmp/sag1/jna/jna7148067692653155490.tmp
But when I check on the disk there is no such file (JVM and SVNKit still running at this time). Shouldn't the file be there? Is it expected? With SVNKit 1.3.5 file was created in temp dir and present as long as JVM/SVNKit was loaded.
I'm asking because the measured performance is still the same with or without JNA in classpath. But as you said it may be related to performance on virtual machine or specific bit mode.
I will let you know how the tests goes on the client end. Thanks!
Commit is failing for almost all operations. Due to this it's not possible for us to use svnkit on Solaris.
Attached is the svnkit log from today.
Thank you for the log file. May I ask you a few more questions regarding this issue:
1. Is this issue only reproducible with JNA library on classpath? On the email your colleague reported that this issue is JNA-related, is that correct?
2. What version of JDK do you use?
3. What version of SVNKit do you use? Did you try newest 1.7.4-v1 version with the new working copy format?
We have installed Solaris OS on a virtual machine and so far did not manage to reproduce the problem both with SVNKit 1.3.5 and newer 1.3.7 version.
Regarding the exception itself (permission denied) - one of the possible reasons for that exception (besides actual permissions problem) is that there is another process running which reads, writes or deletes temporary file at the same time when commit operation is running. Among such processes there are usually antivirus software or indexing programs that tracks and watches files being created or modified. So, if possible, please check if there are such background process running on your Solaris box and disable it to check if it may be the reason of the problem.
Thanks!
1. Yes, the issue is reproducible only with JNA on the classpath. If we remove JNA all tests complete successfully but performance is significantly degraded.
2. JDK is in version: Sun 1.6.0_24 (50.0), VM: Java HotSpot(TM) 64-Bit Server VM, build: 19.1-b02, mixed mode
3. We tried newest 1.7.4-v1 with JNA in classpath and it looks that access denied problem is gone - version prior 1.7.4-v1 were braking for us due to issue.
With 1.7.4-v1 + JNA performance is really weak (average the same as 1.3.5 w/o JNA) so it seems that JNA is not used. Is there a way I can verify that SVNKIT is actually using JNA?
It's good news that with 1.7.4-v1 the issue is resolved however the same performance score as 1.3.5 w/o JNA makes us believe JNA is not used at all (it is in classpath). Could you please help us troubleshooting this?
When running 1.7.4-v1 with JNA we don't see any library related to jnidispatch in temporary dir. For 1.3.5 with JNA - jnidispatch lib is properly created in temp dir and loaded from there.
Verified background processes - there are no other processes that access svnkit temporary files.
Thanks for your help!
SVNKit 1.7.4-v1 uses newer version of JNA (JNA 3.4.0). I've just tested it on Windows and JNA is used by SVNKit. Unfortunately there is no information written to log in that version on whether JNA is actually used, but you may calls SVNJNAUtil.isJNAPresent/Enabled methods at runtime to check whether JNA is present and used.
We will check if JNA is used by 1.7.4-v1 on our VM Solaris.
With JDK 1.6 there is no way to improve performance without JNA been used. However, if you could switch to 1.7 then you may expect better performance without JNA as soon as we add JDK new IO API support to SVNKit, which we expect to do in a few weeks.
Thanks! I'll keep you updated on the status of our investigations.
Solaris version (64 bit):
SunOS unknown 5.10 Generic_147441-01 i86pc i386 i86pc
Java version:
Java(TM) SE Runtime Environment (build 1.6.0_26-b03)
Java HotSpot (TM) Client VM (build 20.1-b02, mixed mode, sharing)
SVNKit 1.7.4-v1 (with additional logging)
With the above configuration I can confirm that JNA (version 3.4.0) is loaded and used, commit works fine both with the old and new working copy formats.
If possible, please try this build of SVNKit in your environment with logging enabled: http://teamcity.tmatesoft.com/viewLog.html?buildId=2703&tab=artifacts&buildTypeId=bt43
To enable debug logging add the following Java VM argument:
where logging.properties is:
Try using that build and then please send me the log file (or attach it to this issue). This log will contain more information on JNA usage.
To disable new working copy format support (so, that working copies are created in the old format, same as used by SVNKit 1.3.7), you may use the following command line argument:
Thanks a lot in advance for your help!
Thank you for the details and new build.
I did the test with provided svnkit snapthot and here are the logs attached - svnkit_logs_for_SNAPSHOT_r9229_v20120518_2250.zip.
With this version I'm getting exceptions the NETWORK: svn: E210004: Malformed network data. Error is persistent with 1.7.4-v2 - I repeated the test with 1.7.4-v1 to verify if it's something introduced with 1.7.4-v2 - with old version test completed successfully.
Please take a look - thanks in advance!
Thank you very much for the log file!
First, regarding "malformed data" error: accordingly to the log it is caused by "Connection Reset" exception, which means that TCP/IP connection is closed on the server side. One of the reasons might be server-side socket write timeout (when it takes too long for the client to process data being received), other reasons are mostly related to the firewall/iptables configuration. You report that 1.7.4-v1 does not suffer from that issue, are you confident about it? May it be that 1.7.4-v1 also fails occasionally with the same error? At least so far I can't see any changes between v1 and v2 that might affect network related code in SVNKit. I will continue to look for.
Second, from the log it could be understood that SVNKit does not use JNA properly in your environment. It loads it, uses but finally receives wrong results and runs pure Java substitution code to get proper file type for instance. This slow downs the execution, plus it may theoretically result in other issues (like originally reported "permission denied" one).
The reason of that problem is that SVNKit JNA-related code for Solaris is only valid for 32-bit system and you run Java in 64-bit mode. On my VM Solaris I could not reproduce JNA-issues when run "jsvn" script (that invokes "java ...") but I did manage to reproduce output similar to those you have in log when add "-d64" to the java command line arguments. Do you pass this argument (-d64 or -server) to "java" program? Could you please try removing it to see if it resolves JNA-related problems?
Meanwhile we will try to add code that handles 64-bit environment on Solaris properly.
Thanks!
I tried your recommendation and set "-d32" switch and verified that JVM was indeed in Java Data Mode 32-bit.
This time there was no 'malformed data' so it really could be transient issue.
Test completed successfully without issues but with poor performance so it seems JNA is still not used.
Please find the log attached: svnkit_logs_v2_20120523 (it's split with zip into two archives since exceeded the upload limit for one file)
Let me know if you would need any other details.
Many thanks for help!
Unfortunately I can't open logs (I've concatenated these two files, but zip program says it is not a valid archive). Could you please run a smaller checkout (like check out a few folders) - this would be enough to see if JNA is used and log will be much shorter.
Another thing to check is whether "-d32" indeed makes JVM run in 32-bit mode. In documentation it is said, that on pure 64-bit Solaris systems, only 64-bit mode is available and 32-bit is ignored. To check this, run "java -d32 version" and "java -version" (or "java -d64 -version") commands. You'll see whether or not 64-bit JVM is used, it should not be used in the first case.
In case -d32 option is ignored and JVM is always ran in 64-bit mode, then you'll have to wait until we add support for 64-bit Solaris to SVNKit JNA-related code. I expect it to be added in a week or so.
Thanks for your suggestions.
I tried the simple commit (logs are small) for both cases -d32 and -d64. Please find attached to the ticket.
I'm including also the screenshot with details for check with 'java -dXX -version'.
Many thanks.
Thank you for the logs. Now your logs are similar to those I'm getting in Virtual Box. JNA was not used properly in 64-bit mode, but it was used properly in 32-bit mode. In case you experience performance issues in 32-bit mode too, then they might be not related to the JNA (or JNA calls themselves might be slow on Solaris in 32 bit mode).
Meanwhile, I've fixed SVNKit JNA code to work properly on 64-bit Solaris, both in trunk and in 1.3.x branch. Fix in 1.3.x is included into 1.3.8 bugfix release that will be published today, and trunk fix will be part of SVNKit 1.7.5 that will be released next week.
Thank you for the update.
I tried the 1.3.8 release in 64-bit mode - looks the JNA library is loaded now and tests passed successfully.
To see dynamic libraries loaded by JVM I used Solaris' 'pldd' - with it I can see that for JVM process there is linked file:
/var/tmp/sag1/jna/jna7148067692653155490.tmp
But when I check on the disk there is no such file (JVM and SVNKit still running at this time).
Shouldn't the file be there? Is it expected?
With SVNKit 1.3.5 file was created in temp dir and present as long as JVM/SVNKit was loaded.
I'm asking because the measured performance is still the same with or without JNA in classpath.
But as you said it may be related to performance on virtual machine or specific bit mode.
I will let you know how the tests goes on the client end.
Thanks!