I'm on the stage of choosing Ldap client for application and UnboundID seems like a good candidate (version 2.3.5).
I've made some simple tests and found only on thing that looks strange.
Maybe someone can help me understand or fix it:
When running the same search using different clients I can see ldap (OpenDJ 2.5.0-Xpress1) etime for UnboundID is very bad comparing to other clients:
(classes have maaany fields but user has only one field set)
We strive to make the UnboundID LDAP SDK as fast as possible, and earlier testing (http://www.dirmgr.com/blog/2011/5/31/comparing-java-ldap-sdk-performance.html) demonstrated it to be substantially faster than other Java-based LDAP APIs. However, I don't think that is really a factor in this case.
In a directory server, the reported etime generally reflects the length of time the server spent processing the operation, and generally has nothing to do with the client API. Obviously, the server can't know how long it took the client to construct and send the request, so the timer can only start once the request has reached the server. Similarly, the server can't know how long it took the client to receive or decode the response, and it's very likely the case that the call to write the data returns after it's just been placed in the transmit buffer without necessarily even having been sent out over the network yet. So there is very likely something else going on here that explains the difference.
The first thing to point out is that performing a single operation is not a good way to measure performance. There are several reasons for this:
. When you perform an operation, the server may need to access data that has not yet been pulled into one or more of the various caches the server may use to help performance. In this case, since it looks like you tested the operation with the UnboundID SDK first, then it may well be that the index for the identifier attribute, the entry being matched, and/or some other data hasn't been accessed since the server was started and therefore may take substantially longer to retrieve the first time.
. Java-based applications (and it sounds like you're using the OpenDJ server, which is Java-based) may exhibit inconsistent performance initially, as the JVM may not have yet been able to perform JIT compilation to dramatically improve the speed of certain operations. Therefore, earlier operations may require interpreting JVM bytecode while later operations may be processed with native code. Further, if an operation triggers JIT compilation, the time required to perform that compilation may also come into play.
. General system jitter may also come into play. Maybe when the request is received, there was some other process active on the system that required enough CPU, disk, memory, or network processing to interfere with the directory server's access to those resources. Obviously, you shouldn't run other expensive processes on a system when trying to assess performance, but with only a single operation, even a very short-lived process or quick burst of activity could cause such interference.
For these and other reasons, it is strongly recommended that performance testing involve performing a lot of operations so that you can be sure that all of the caches have been warmed up and JIT compilation is out of the way. For example, if you change your program to repeat the search a million times and then look at the average of the last hundred thousand, you're probably going to get a much better feel for what performance is really like. In the example code you provided, this could be done just by changing the line:
ldapConnection.search(request);
to be:
for (int i=0; i < 1000000; i++) { ldapConnection.search(request); }
If testing with a large number of requests shows that there still is some difference in the time required to process the requests from different clients, then there may be some small difference between the requests that could account for the variation. Even though the access log snippet you provided indicates that the searches are identical, it could be that there is a difference in the request in some other portion of the request that doesn't show up in the log message. To determine whether that may be the case, you should take a low-level look at exactly what requests are being sent to the server.
While this can be done with a network packet capture tool like wireshark (or a more bare-bones utility like snoop or tcpdump), an easier approach would probably be to use the ldap-debugger tool provided with the LDAP SDK. This tool operates as a very simple LDAP proxy server that can provide detailed information about the requests and responses that pass through it. To use it, point the ldap-debugger tool at the directory server, and then point your application at the ldap-debugger. For example,
Then, instead of pointing your client at 127.0.0.1:1389, you can point it at 127.0.0.1:2389. The resulting ldap-debugger log will provide detailed information about exactly what requests the client is sending and exactly what responses the server is returning.
I'm pretty confident that the issue you're seeing here is really one of the "warmup" issues I mentioned, but if it doesn't seem to be that, and it looks like all the requests and responses are identical, then it may require some deeper investigation to figure out what the problem is.
Neil
If you would like to refer to this comment somewhere else in this project, copy and paste the following link:
First of all: thanks for you response. I really appreciate when someone explains everything step by step not only as a response to the question by also in form of a tutorial for others who will read this and may use it to resolve their problems.
I've been testing this requests in different order but test of 100 000 requests is of course always a good one.
btw. maybe would be helpful to someone (calculate avg from 100 000; can be done better but it works):
less access | grep etime | cut -d '=' -f 7 | awk '{ sum += $1 } END { print sum }' | awk '{ sum = $1 / 100000 } END { printf "%i\n", sum }'
Anyway:
Using debugger I found that there was a difference in those queries - they seem same in access log but they are quite different:
Code:
SearchRequest request = new SearchRequest(base , SearchScope.ONE, f, makeLdapClass(className1), makeLdapClass(className2));
this is valid and returns only entries from those classes. But using command line tool and JMeter I made a mistake:
instead of using className1 className2 as attributes it was className1,className2 and it makes a difference...
Somehow (I'm not an expert in ldap request format) it returns everything from a user entry so it works like "*".
The fact that it's faster doesn't change anything - comparing two different requests does not make any sense.
Hi,
I'm on the stage of choosing Ldap client for application and UnboundID seems like a good candidate (version 2.3.5).
I've made some simple tests and found only on thing that looks strange.
Maybe someone can help me understand or fix it:
When running the same search using different clients I can see ldap (OpenDJ 2.5.0-Xpress1) etime for UnboundID is very bad comparing to other clients:
(classes have maaany fields but user has only one field set)
UnboundID:
[26/Jan/2014:13:47:37 +0100] CONNECT conn=821 from=127.0.0.1:48174 to=127.0.0.1:1389 protocol=LDAP
[26/Jan/2014:13:47:37 +0100] BIND REQ conn=821 op=0 msgID=1 version=3 type=SIMPLE dn="cn=Directory Manager"
[26/Jan/2014:13:47:37 +0100] BIND RES conn=821 op=0 msgID=1 result=0 authDN="cn=Directory Manager,cn=Root DNs,cn=config" etime=284778
[26/Jan/2014:13:47:37 +0100] SEARCH REQ conn=821 op=1 msgID=2 base="ou=people,dc=example,dc=com" scope=singleLevel filter="(identifier=0000001)" attrs="@userProperties,@userInheritedProperties"
[26/Jan/2014:13:47:37 +0100] SEARCH RES conn=821 op=1 msgID=2 result=0 nentries=1 etime=3081817
[26/Jan/2014:13:47:38 +0100] DISCONNECT conn=821 reason="Client Disconnect"
ldapsearch (OpenDJ script under /bin)
[26/Jan/2014:13:47:49 +0100] CONNECT conn=822 from=127.0.0.1:48176 to=127.0.0.1:1389 protocol=LDAP
[26/Jan/2014:13:47:49 +0100] BIND REQ conn=822 op=0 msgID=1 version=3 type=SIMPLE dn="cn=Directory Manager"
[26/Jan/2014:13:47:49 +0100] BIND RES conn=822 op=0 msgID=1 result=0 authDN="cn=Directory Manager,cn=Root DNs,cn=config" etime=482330
[26/Jan/2014:13:47:49 +0100] SEARCH REQ conn=822 op=1 msgID=2 base="ou=people,dc=example,dc=com" scope=singleLevel filter="(identifier=0000001)" attrs="@userProperties,@userInheritedProperties"
[26/Jan/2014:13:47:49 +0100] SEARCH RES conn=822 op=1 msgID=2 result=0 nentries=1 etime=347535
[26/Jan/2014:13:47:49 +0100] UNBIND REQ conn=822 op=2 msgID=3
[26/Jan/2014:13:47:49 +0100] DISCONNECT conn=822 reason="Client Unbind"
Jmeter (LDAP Extended Request)
[26/Jan/2014:13:47:57 +0100] CONNECT conn=823 from=127.0.0.1:48177 to=127.0.0.1:1389 protocol=LDAP
[26/Jan/2014:13:47:57 +0100] BIND REQ conn=823 op=0 msgID=1 version=3 type=SIMPLE dn="cn=Directory Manager"
[26/Jan/2014:13:47:57 +0100] BIND RES conn=823 op=0 msgID=1 result=0 authDN="cn=Directory Manager,cn=Root DNs,cn=config" etime=553692
[26/Jan/2014:13:47:57 +0100] SEARCH REQ conn=823 op=1 msgID=2 base="ou=people,dc=example,dc=com" scope=singleLevel filter="(identifier=0000001)" attrs="@userProperties,@userInheritedProperties"
[26/Jan/2014:13:47:57 +0100] SEARCH RES conn=823 op=1 msgID=2 result=0 nentries=1 etime=684003
[26/Jan/2014:13:47:57 +0100] UNBIND REQ conn=823 op=2 msgID=3
[26/Jan/2014:13:47:57 +0100] DISCONNECT conn=823 reason="Client Unbind"
Simple App Jave Code:
We strive to make the UnboundID LDAP SDK as fast as possible, and earlier testing (http://www.dirmgr.com/blog/2011/5/31/comparing-java-ldap-sdk-performance.html) demonstrated it to be substantially faster than other Java-based LDAP APIs. However, I don't think that is really a factor in this case.
In a directory server, the reported etime generally reflects the length of time the server spent processing the operation, and generally has nothing to do with the client API. Obviously, the server can't know how long it took the client to construct and send the request, so the timer can only start once the request has reached the server. Similarly, the server can't know how long it took the client to receive or decode the response, and it's very likely the case that the call to write the data returns after it's just been placed in the transmit buffer without necessarily even having been sent out over the network yet. So there is very likely something else going on here that explains the difference.
The first thing to point out is that performing a single operation is not a good way to measure performance. There are several reasons for this:
. When you perform an operation, the server may need to access data that has not yet been pulled into one or more of the various caches the server may use to help performance. In this case, since it looks like you tested the operation with the UnboundID SDK first, then it may well be that the index for the identifier attribute, the entry being matched, and/or some other data hasn't been accessed since the server was started and therefore may take substantially longer to retrieve the first time.
. Java-based applications (and it sounds like you're using the OpenDJ server, which is Java-based) may exhibit inconsistent performance initially, as the JVM may not have yet been able to perform JIT compilation to dramatically improve the speed of certain operations. Therefore, earlier operations may require interpreting JVM bytecode while later operations may be processed with native code. Further, if an operation triggers JIT compilation, the time required to perform that compilation may also come into play.
. General system jitter may also come into play. Maybe when the request is received, there was some other process active on the system that required enough CPU, disk, memory, or network processing to interfere with the directory server's access to those resources. Obviously, you shouldn't run other expensive processes on a system when trying to assess performance, but with only a single operation, even a very short-lived process or quick burst of activity could cause such interference.
For these and other reasons, it is strongly recommended that performance testing involve performing a lot of operations so that you can be sure that all of the caches have been warmed up and JIT compilation is out of the way. For example, if you change your program to repeat the search a million times and then look at the average of the last hundred thousand, you're probably going to get a much better feel for what performance is really like. In the example code you provided, this could be done just by changing the line:
to be:
for (int i=0; i < 1000000; i++) { ldapConnection.search(request); }If testing with a large number of requests shows that there still is some difference in the time required to process the requests from different clients, then there may be some small difference between the requests that could account for the variation. Even though the access log snippet you provided indicates that the searches are identical, it could be that there is a difference in the request in some other portion of the request that doesn't show up in the log message. To determine whether that may be the case, you should take a low-level look at exactly what requests are being sent to the server.
While this can be done with a network packet capture tool like wireshark (or a more bare-bones utility like snoop or tcpdump), an easier approach would probably be to use the ldap-debugger tool provided with the LDAP SDK. This tool operates as a very simple LDAP proxy server that can provide detailed information about the requests and responses that pass through it. To use it, point the ldap-debugger tool at the directory server, and then point your application at the ldap-debugger. For example,
tools/ldap-debugger --hostname 127.0.0.1 --port 1389 --listenPort 2389 \ --outputFile ldap-debugger.logThen, instead of pointing your client at 127.0.0.1:1389, you can point it at 127.0.0.1:2389. The resulting ldap-debugger log will provide detailed information about exactly what requests the client is sending and exactly what responses the server is returning.
I'm pretty confident that the issue you're seeing here is really one of the "warmup" issues I mentioned, but if it doesn't seem to be that, and it looks like all the requests and responses are identical, then it may require some deeper investigation to figure out what the problem is.
Neil
First of all: thanks for you response. I really appreciate when someone explains everything step by step not only as a response to the question by also in form of a tutorial for others who will read this and may use it to resolve their problems.
I've been testing this requests in different order but test of 100 000 requests is of course always a good one.
btw. maybe would be helpful to someone (calculate avg from 100 000; can be done better but it works):
less access | grep etime | cut -d '=' -f 7 | awk '{ sum += $1 } END { print sum }' | awk '{ sum = $1 / 100000 } END { printf "%i\n", sum }'Anyway:
Using debugger I found that there was a difference in those queries - they seem same in access log but they are quite different:
Code:
this is valid and returns only entries from those classes. But using command line tool and JMeter I made a mistake:
instead of using className1 className2 as attributes it was className1,className2 and it makes a difference...
Somehow (I'm not an expert in ldap request format) it returns everything from a user entry so it works like "*".
The fact that it's faster doesn't change anything - comparing two different requests does not make any sense.
When I break my valid request to:
I get same results.
Thanks for your help and showing how to debug ldap requests using you tool.
Jacek