Hash generation using java digest gets slower in time

Question

I'm having a real curious situation, in a production environment using wildfly 8.2 and Java 1.7.

The situation is that when the server is been up for more than 2 weeks the login begins to drop performance. I have been looking for clues that may indicate where the issue is. Then after doing some testing, I came to the conclusion that the problem is when the password inserted in plain text is been encrypted to be compared with the one already inserted.

When the function that encrypts the password is executed it takes almost 2 minutes, but when the server is restarted the same execution takes less than 30 seconds.

The encryption is using java.security.MessageDigest to generate the hash. Specifically using SHA-256 with 50000 iterations. Any idea why this process could get slower with time? I'm using /dev/urandom for the generation of random so that shouldn't be the problem.

Here is the funtion code:

protected byte[] hash(byte[] bytes, byte[] salt, int hashIterations) throws UnknownAlgorithmException {
    MessageDigest digest = getDigest(getAlgorithmName());
    if (salt != null) {
        digest.reset();
        digest.update(salt);
    }
    byte[] hashed = digest.digest(bytes);
    int iterations = hashIterations - 1; //already hashed once above
    //iterate remaining number:
    for (int i = 0; i < iterations; i++) {
        digest.reset();
        hashed = digest.digest(hashed);
    }
    return hashed;
}

Answer 1

After somedays of research I have finally found the answer to my question. I want to share it here in case it is useful to someone else.

The problem was caused because of the code cache memory. I was focusing on the heap memory and I didn't see any problem, but when I inspect the non-heap memory I find out that just as the login process began to slow down there was a drop of more than half on the code cache memory used.

Investigating this memory, I have found that when there are large drops in this space, it may happen that the JIT compiler stops working. In conclusion, that was what was happening, and having the JIT compiler turned off caused that each iteration of my encryption loop had to be interpreted each execution, which logically made the process much slower.

Here I leave some links that I find helpful in this topic.

[1] - https://www.quora.com/In-Java-what-exactly-will-the-JVM-interpreter-and-the-JIT-compiler-do-with-the-bytecode

[2] - https://www.atlassian.com/blog/archives/codecache-is-full-compiler-has-been-disabled

Thanks to those who take the time to answer it anyways

Answer 2

Get rid of the statement: int iterations = hashIterations - 1; and just use hashIterations.

In the best case it reduces the iterations from 50000 (in the stated case) to 49999 and in the worst case causes integer underflow and increases the iterations to the max value of int.

At a minimum guard against subtracting 1 when hashIterations is zero.

Also consider instrumentation, for debugging, by logging the value of iterations.

Answer 3

Why will somebody close this??? Maybe because there's nothing there what could probably cause the problem.

While digest.digest is normally the time-consuming part, it's a pure computation and there's nothing what could slow it down. So what remains is getAlgorithmName() and getDigest(String). The former is probably a trivial getter, but the latter probably uses MessageDigest.getInstance which locates the digest. Just guessing: There's a lookup over all security providers and all the stuff they provide and someone may lengthen this list somehow.

You can sort of benchmark this library method even in production: Just copy the method in a new source file and add some logging and some code invoking it periodically (or manually, if you prefer). When the slowdown happens, you'll have something to compare to and you'll find some detailed timings in your logs.

When all imaginable reasons are exhausted, try the non-imaginable ones like varying iterations (which you believe is a constant), etc.