Wednesday, August 05, 2009

Something's broken in JNDI ?

Consider the following unit test :


package ldapcrap;

import java.util.Hashtable;

import javax.naming.NamingException;
import javax.naming.directory.DirContext;
import javax.naming.directory.InitialDirContext;

import junit.framework.TestCase;

@SuppressWarnings("unchecked")
public class CrapTest extends TestCase {

private Hashtable env;

@Override
protected void setUp() throws Exception {
super.setUp();

env = new Hashtable();

env.put("java.naming.factory.initial",
"com.sun.jndi.ldap.LdapCtxFactory");
env.put("java.naming.provider.url", "ldap://10.0.0.5");
env.put(DirContext.SECURITY_AUTHENTICATION, "simple");
}

public void testJNDIisCrap() throws NamingException {
DirContext ctx = null;
try {
ctx = new InitialDirContext(env);
} catch (Throwable t) {
fail("test failed");
} finally {
ctx.close();
}
}

public void testInALoop() throws NamingException {
long time;
int COUNT;

COUNT = 1000;
time = System.currentTimeMillis();
for (int i = 0; i < COUNT; i++) {
testJNDIisCrap();
}
time = System.currentTimeMillis() - time;
System.out.println("did "+COUNT+" in "+(time/1000)+"second(s).");

COUNT = 10000;
time = System.currentTimeMillis();
for (int i = 0; i < COUNT; i++) {
testJNDIisCrap();
}
time = System.currentTimeMillis() - time;
System.out.println("did "+COUNT+" in "+(time/1000)+"second(s).");

COUNT = 100000;
time = System.currentTimeMillis();
for (int i = 0; i < COUNT; i++) {
testJNDIisCrap();
}
time = System.currentTimeMillis() - time;
System.out.println("did "+COUNT+" in "+(time/1000)+"second(s).");
}

@Override
protected void tearDown() throws Exception {
super.tearDown();
}
}


Here's what it shows when openldap is running on 32bit debian etch:
did 1000 in 2second(s).
did 10000 in 28second(s).
did 100000 in 441second(s).

Something sounds wrong with those results as the unit test is linear : open/close, open/close. As long as we do not get 2, 20, 200 or something approaching, either my test code is wrong, or some server configuration is wrong.

The results on 64bit lenny are:
did 1000 in 2second(s).
did 10000 in 19second(s).

No third result, it broke and the test failed with some useless null pointer. Let's "strace -f" the slapd process on lenny :
did 1000 in 13second(s).
did 10000 in 382second(s).

Ok, will take too long and seems stalled. Will write strace output to a file "strace -f -o slapd.log".

Starts good :
did 1000 in 6second(s).
did 10000 in 61second(s).

But then...
did 100000 in 1049second(s).

I expected between 500 & 620 seconds (I hoped the jvm JIT will do its job). I used my computer in the meantime, but not that much.

Still analysing the strace output, but if someone knows what is wrong in my test...